-

2024-11-29 02:55:38

adminsforum@hubzilla.org

Markus wrote the following post Fri, 29 Nov 2024 02:55:58 +0100

at the moment my performance when calling the PubStream is moderate in the Hubzilla log I have the following entry:

│2024-11-29T01:50:01Z:LOG_ERR:775d771aaa:dba_driver.php:471:db_logger: dba_pdo: ERROR: SELECT workerq_id FROM workerq WHERE workerq_reservationid IS NOT NULL AND workerq_processtimeout < UTC_TIMESTAMP() FOR UPDATE NOWAIT      │
│SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

I see that the timestamp is wrong. It should be 2:50, one hour later. Can anyone tell me more?

show all 17 comments

2024-11-29 07:07:37

Mario Vavti

mario@hub.somaton.com

The timestamp is in UTC. The error you see is related to the queueworker and is expected due to the nowait directive.

Du you see an oom issue (maybe a huge thread?) or a timeout error in php logs?

2024-11-29 07:35:43

Markus

markus@hubzilla.markusgarlichs.de

@Mario Vavti the only thing that is conspicuous at the moment are these entries in the Apache Error.log:

[Fri Nov 29 06:28:05.210931 2024] [proxy_fcgi:error] [pid 275079:tid 275132] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:33978] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:33:06.765499 2024] [proxy_fcgi:error] [pid 275079:tid 275137] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:33040] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:36:52.503972 2024] [proxy_fcgi:error] [pid 344776:tid 344802] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:45992] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:39:55.403954 2024] [proxy_fcgi:error] [pid 344901:tid 344922] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:60758] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:44:07.042090 2024] [proxy_fcgi:error] [pid 344777:tid 344823] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:49038] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:45:38.362308 2024] [proxy_fcgi:error] [pid 344776:tid 344786] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:40002] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream?f=&zid=mario%40hub.somaton.com
[Fri Nov 29 06:46:22.769456 2024] [proxy_fcgi:error] [pid 344776:tid 344791] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:55124] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:49:36.188824 2024] [proxy_fcgi:error] [pid 344777:tid 344818] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:56268] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 06:55:50.947707 2024] [proxy_fcgi:error] [pid 344901:tid 344917] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:47366] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream
[Fri Nov 29 07:08:52.262035 2024] [proxy_fcgi:error] [pid 344777:tid 344828] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:46636] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/pubstream?f=&zid=mario%40hub.somaton.com
[Fri Nov 29 07:16:16.550226 2024] [proxy_fcgi:error] [pid 344901:tid 344922] (70007)The timeout specified has expired: [remote xxx.xxx.xxx.xxx:37842] AH01075: Error dispatching request to : (polling), referer: https://hubzilla.markusgarlichs.de/network/?f=&pf=1&unseen=1&cid=25

At the moment the PubStream is not loading at all. But everything else is working. HQ, channel, etc.

Finally I get this error in the Apache access.log:

│xxx.xxx.xxx.xxx - - [29/Nov/2024:06:54:50 +0100] "GET /update/pubstream/load?p=2&fh=1&order=comment&_=1732859690748 HTTP/2.0" 504 302 "https://hubzilla.markusgarlichs.de/pubstream" "Mozilla/5.0 (X11; Linux x86_64; rv:133.0) Gecko

But you've probably already seen it too.

2024-11-29 11:19:44

Harald Eilertsen

harald@hub.volse.no

@Markus You're using php_fpm with Apache? If so, you can check the slowlog (if it's enabled) to find what's taking so long that the process times out.

2024-11-29 16:32:12

Markus

markus@hubzilla.markusgarlichs.de

@Harald Eilertsen @Mario Vavti I've just returned home and everything is running as usual at the moment. I have activated the slow log, if there are any interruptions again I will post the log.

So far, I can only say that these problems started 2 or 3 days ago. In this period, php8.2 updates fall.

2024-11-29 22:06:13

Markus

markus@hubzilla.markusgarlichs.de

This was one of those cases. Called up the Pubstream at 21:53 and received it at 21:59.

Slowlog:

[29-Nov-2024 21:53:45]  [pool www] pid 1350563
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013a10] query() /var/www/hubzilla/include/dba/dba_pdo.php:81
[0x00007f422e013930] q() /var/www/hubzilla/include/dba/dba_driver.php:375
[0x00007f422e0138a0] dbq() /var/www/hubzilla/Zotlabs/Module/Network.php:475
[0x00007f422e0132c0] get() /var/www/hubzilla/Zotlabs/Module/Update.php:37
[0x00007f422e013210] get() /var/www/hubzilla/Zotlabs/Web/Router.php:290
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

[29-Nov-2024 21:53:51]  [pool www] pid 1479548
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013760] query() /var/www/hubzilla/include/dba/dba_pdo.php:81
[0x00007f422e013680] q() /var/www/hubzilla/include/dba/dba_driver.php:375
[0x00007f422e0135f0] dbq() /var/www/hubzilla/Zotlabs/Module/Pubstream.php:217
[0x00007f422e0132c0] get() /var/www/hubzilla/Zotlabs/Module/Update.php:37
[0x00007f422e013210] get() /var/www/hubzilla/Zotlabs/Web/Router.php:290
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

[29-Nov-2024 21:57:24]  [pool www] pid 1485985
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013a20] curl_exec() /var/www/hubzilla/include/network.php:164
[0x00007f422e013840] z_fetch_url() /var/www/hubzilla/Zotlabs/Lib/Activity.php:131
[0x00007f422e0136f0] fetch() /var/www/hubzilla/Zotlabs/Lib/ActivityStreams.php:342
[0x00007f422e013640] fetch_property() /var/www/hubzilla/Zotlabs/Lib/ActivityStreams.php:420
[0x00007f422e013530] get_compound_property() /var/www/hubzilla/Zotlabs/Lib/ActivityStreams.php:104
[0x00007f422e013450] __construct() /var/www/hubzilla/extend/addon/hzaddons/pubcrawl/Mod_Inbox.php:93
[0x00007f422e013210] post() /var/www/hubzilla/Zotlabs/Web/Router.php:276
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

[29-Nov-2024 21:57:24]  [pool www] pid 1490162
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013760] query() /var/www/hubzilla/include/dba/dba_pdo.php:81
[0x00007f422e013680] q() /var/www/hubzilla/include/dba/dba_driver.php:375
[0x00007f422e0135f0] dbq() /var/www/hubzilla/Zotlabs/Module/Pubstream.php:217
[0x00007f422e0132c0] get() /var/www/hubzilla/Zotlabs/Module/Update.php:37
[0x00007f422e013210] get() /var/www/hubzilla/Zotlabs/Web/Router.php:290
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

[29-Nov-2024 21:57:32]  [pool www] pid 1490386
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013760] query() /var/www/hubzilla/include/dba/dba_pdo.php:81
[0x00007f422e013680] q() /var/www/hubzilla/include/dba/dba_driver.php:375
[0x00007f422e0135f0] dbq() /var/www/hubzilla/Zotlabs/Module/Pubstream.php:217
[0x00007f422e0132c0] get() /var/www/hubzilla/Zotlabs/Module/Update.php:37
[0x00007f422e013210] get() /var/www/hubzilla/Zotlabs/Web/Router.php:290
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

[29-Nov-2024 21:58:48]  [pool www] pid 1490386
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013760] query() /var/www/hubzilla/include/dba/dba_pdo.php:81
[0x00007f422e013680] q() /var/www/hubzilla/include/dba/dba_driver.php:375
[0x00007f422e0135f0] dbq() /var/www/hubzilla/Zotlabs/Module/Pubstream.php:217
[0x00007f422e0132c0] get() /var/www/hubzilla/Zotlabs/Module/Update.php:37
[0x00007f422e013210] get() /var/www/hubzilla/Zotlabs/Web/Router.php:290
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

[29-Nov-2024 21:59:32]  [pool www] pid 1490386
script_filename = /var/www/hubzilla/index.php
[0x00007f422e013760] query() /var/www/hubzilla/include/dba/dba_pdo.php:81
[0x00007f422e013680] q() /var/www/hubzilla/include/dba/dba_driver.php:375
[0x00007f422e0135f0] dbq() /var/www/hubzilla/Zotlabs/Module/Pubstream.php:217
[0x00007f422e0132c0] get() /var/www/hubzilla/Zotlabs/Module/Update.php:37
[0x00007f422e013210] get() /var/www/hubzilla/Zotlabs/Web/Router.php:290
[0x00007f422e013140] Dispatch() /var/www/hubzilla/Zotlabs/Web/WebServer.php:112
[0x00007f422e013090] run() /var/www/hubzilla/index.php:14

2024-11-29 23:12:42

Harald Eilertsen

harald@hub.volse.no

@Markus Probably the curl call. If the remote site is slow to answer (or don't respond at all) that can cause the request to time out.

2024-11-29 23:16:40

Mario Vavti

mario@hub.somaton.com

@Harald Eilertsen the curl call is not related to the pubstream...

2024-11-29 23:31:04

Harald Eilertsen

harald@hub.volse.no

@Mario Vavti That may be, then it's the database being slow. Which is no surprise. Perhaps increase the number of DB processes.

2024-11-30 00:04:21

Markus

markus@hubzilla.markusgarlichs.de

@Mario Vavti @Harald Eilertsen I have increased the innodb_buffer_pool_size a bit and now the pubstream starts quite fast. However, I am reaching a pain threshold and might have to contact my provider to get more memory. I will continue to monitor it and then give you more feedback. Thank you so far.

2024-11-30 01:39:24

Mario Vavti

mario@hub.somaton.com

@Markus it is weird that your channel loads fast but at the same time pubstream does not. Not sure if an optimize table item; will improve anything, but you could try...

In any case it would be great if you also turned on slow log for the DB so we can see which query it is...

2024-11-30 01:53:35

Markus

markus@hubzilla.markusgarlichs.de

@Mario Vavti Yes, of course - it's activated and I'll post the log asap.

2024-11-30 18:22:28

Markus

markus@hubzilla.markusgarlichs.de

@Mario Vavti

it is weird that your channel loads fast but at the same time pubstream does not.

Yes, it's strange - the pubstream is now taking a little longer to build up again. I haven't seen this from Hubzilla before and had praised it for its good performance. I'll keep the mariadb slow log running and think I'll be able to post the log tomorrow.

2024-12-01 09:58:01

Mario Vavti

mario@hub.somaton.com

Do you have Expiration period in days for imported (grid/network) content set for your hub in admin/site?

2024-12-01 10:08:32

Markus

markus@hubzilla.markusgarlichs.de

@Mario Vavti yes, 30 Days. In the meantime, however, I have noticed that the posts from a Lemmy group I subscribed to have been delivered to me only hesitantly. I unsubscribed from the group as a test and things seem to be going better at the moment. I'll let you know how things continue to go.

2024-12-02 15:55:36

Alfred Bühler

abu@hub.alfredbuehler.ch

@Markus I detected tons of such messages in my dbfail.log a few days ago, but without having any performance issue. To get rid of them, I did the following:

Modified the setting db_skip_locked_supported in .htconfig.php.

// Set this to 1 if your DB backend supports skip locked.
// This is known to be the case for
// postgresql > 9.5, mysql > 8.0 and mariadb > 10.6
App::$config['system']['db_skip_locked_supported'] = 1;

Increased the cron interval from 5 to 10 minutes.

Since then, the messaged are vanished.

2024-12-02 19:16:43

Markus

markus@hubzilla.markusgarlichs.de

@Alfred Bühler Thank you for the suggestion. However, I have no error messages in the MariaDB error.log. It has gotten a little better since I canceled some Lemmy groups but the Pubstream is still not running smoothly. I have applied the changes you mentioned as a test, but without any significant change in performance.

2024-12-05 23:24:33

Mario Vavti

mario@hub.somaton.com

The issue has been identified and resolved in this commit: #^https://framagit.org/hubzilla/core/-/commit/15b6353c1c970abbb5bf2d89a11a0812aab2414f