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

[Rick Romero]

FYI - Running:
TRUNCATE `horde_imap_client_data` ;
TRUNCATE `horde_imap_client_message` ;
TRUNCATE `horde_imap_client_metadata` ;

Solved the problem.  (Even with a 600 second timeout it wouldn't complete)

Rick

Quoting rick at havokmon.com:

> 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.
>
> --
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/To unsubscribe, mail:
> horde-unsubscribe at lists.horde.org