[horde] DEBUG doesn't show slow query - max exec time exceeded

rick at havokmon.com rick at havokmon.com
Wed Sep 10 15:54:27 UTC 2014


I can't login to Horde5 with ONE account (my own of course).  All other 
accounts work, no one else seems to have an issue.
Basically, I leave my session open all night, and when I came in this 
morning my last email shown was around 3am, and the web interface would 
say 'Server not responding'.  After logging out, and back in, I now 
ALWAYS get:

ErrorException Object
(
     [message:protected] => Maximum execution time of 30 seconds exceeded
     [string:Exception:private] =>
     [code:protected] => 0
     [file:protected] => /usr/share/php/Horde/Db/Adapter/Base.php
     [line:protected] => 747
     [trace:Exception:private] => Array
         (
             [0] => Array
                 (
                     [function] => catchFatalError
                     [class] => Horde_ErrorHandler
                     [type] => ::
                     [args] => Array
                         (
                         )

                 )

         )

     [previous:Exception:private] =>
     [severity:protected] => 1
     [logged] => 1


Enabling DEBUG, I managed to pull the following out:

2014-09-10T10:22:48-05:00 DEBUG: HORDE5 [horde] Horde_Prefs: Storing 
preference value (last_login) [pid 3282 on line 82 of 
"/usr/share/horde/lib/LoginTasks/Task/LastLogin.php"]
2014-09-10T10:22:48-05:00 DEBUG: HORDE5 [horde] Horde_Prefs: Storing 
preference value (last_logintasks) [pid 3282 on line 98 of 
"/usr/share/php/Horde/Core/LoginTasks/Backend/Horde.php"]
2014-09-10T10:22:48-05:00 DEBUG: HORDE5 [gollem] Load config file 
(conf.php; app: gollem) [pid 3282 on line 109 of 
"/usr/share/php/Horde/Registry/Loadconfig.php"]
2014-09-10T10:22:49-05:00 DEBUG: HORDE5 [imp] SQL  (0.0003s)
         SELECT t.field, t.data FROM horde_imap_client_data d INNER JOIN
           horde_imap_client_metadata t ON d.messageid = t.messageid 
WHERE
           d.hostspec = 'localhost' AND d.port = '1143' AND d.username =
           'rick at havokmon.com' AND d.mailbox = 'INBOX' AND (t.field = 
'_m' OR
           t.field = 'uidvalid') [pid 3282 on line 320 of 
"/usr/share/php/Horde/Db/Adapter/Mysqli.php"]
2014-09-10T10:22:49-05:00 DEBUG: HORDE5 [imp] Horde_HashTable_Memcache: 
Retrieved keys 
(horde5Horde_Db_Adapter_Mysqli0571bbe8tables/columns/horde_imap_client_metadata) 
[pid 3282 on line 233 of "/usr/share/php/Horde/HashTable/Base.php"]
2014-09-10T10:22:49-05:00 DEBUG: HORDE5 [imp] SQL  (0.0002s)
         SELECT t.field, t.data FROM horde_imap_client_data d INNER JOIN
           horde_imap_client_metadata t ON d.messageid = t.messageid 
WHERE
           d.hostspec = 'localhost' AND d.port = '1143' AND d.username =
           'rick at havokmon.com' AND d.mailbox = 'INBOX' AND (t.field = 
'uidvalid') [pid 3282 on line 320 of 
"/usr/share/php/Horde/Db/Adapter/Mysqli.php"]
2014-09-10T10:22:49-05:00 DEBUG: HORDE5 [imp] Horde_HashTable_Memcache: 
Retrieved keys 
(horde5Horde_Db_Adapter_Mysqli0571bbe8tables/columns/horde_imap_client_metadata) 
[pid 3282 on line 233 of "/usr/share/php/Horde/HashTable/Base.php"]
2014-09-10T10:22:49-05:00 DEBUG: HORDE5 [imp] SQL  (0.0007s)
         SELECT DISTINCT t.msguid FROM horde_imap_client_data d INNER 
JOIN
           horde_imap_client_message t ON d.messageid = t.messageid WHERE
           d.hostspec = 'localhost' AND d.port = '1143' AND d.username =
           'rick at havokmon.com' AND d.mailbox = 'INBOX' [pid 3282 on line 
320 of "/usr/share/php/Horde/Db/Adapter/Mysqli.php"]
-- SNIP -- There's other users using ActiveSync.. these appear to all be 
related to me
2014-09-10T10:23:18-05:00 EMERG: HORDE5 [imp] Maximum execution time of 
30 seconds exceeded [pid 3282 on line 747 of 
"/usr/share/php/Horde/Db/Adapter/Base.php"]
2014-09-10T10:23:18-05:00 DEBUG: HORDE5 1. 
Horde_ErrorHandler::catchFatalError()
2014-09-10T10:23:18-05:00 DEBUG: HORDE5 [imp] SQL  (0.0003s)
      (Some other Query)

It appears, under normal circumstance, that the 'Some Other Query' is 
replaced with the actual QUERY in debug mode.  But in this case, it's 
not shown.  While this query is 'waiting', my MySQL server is not 
processing any requests, so I'm really unsure what's really going on.  
I've deleted all my prefs (as that sometimes has hosed things in the 
past, to no avail).

I've also logged in as a different admin user and manually deleted my 
sessions from the horde_sessionHandler table, just to be sure.
Also, I've cleaned up my INBOX incase it was related to INBOX size. I 
see the next table is probably horde_imap_client_message - how would I 
clean that up for just my user?  Or can those safely be emptied?


MAYBE RELATED?
I do also see these, but I can't find an 8Mb limit anywhere - and it 
doesn't seem to be for my user.

2014-09-10T10:22:57-05:00 DEBUG: HORDE5 [imp] SQL  (0.0008s)
         SELECT alarm_id, alarm_uid, alarm_start, alarm_end, 
alarm_methods,
         <etc>  FOR A DIFFERENT USER.
2014-09-10T10:22:57-05:00 DEBUG: HORDE5 [imp] Max memory usage: 7077888 
bytes

I run Horde5 on Debian via lighttpd and php-cgi - 128Mb max memory usage 
(I upped to 180 for testing, no change for either error)

Any suggestions would be greatly appreciated.



More information about the horde mailing list