I'm also seeing a somewhat similar problem, in addition to the delay I'm also seeing dbmail-imapd taking 100% CPU during that session.
I'm attaching the log file for dbmail with TRACE_SYSLOG = 10 This logfile is only for "SEARCH ALL UNDELETED" IMAP command. My database is big, ~300GB, I've also tested this with creating a brand new db in mysql and I wasn't able to reproduce the problem, even though the mysql SELECT statement returns right away, (I'm not sure though) but it seems to be somehow related to database. Thank you for any help that anybody can provide. ----- Original Message ---- From: Erwin Lubbers <[email protected]> To: DBMail mailinglist <[email protected]> Sent: Thu, July 1, 2010 1:47:18 AM Subject: Re: [Dbmail] dbmail very slow performance on imap SEARCH and SORT commands Hi Paul, A bit delay in my answer. But I did make a trace with the level set to 5. I did copy-and-paste the following commands directly after the strace command, so there is no delay seen while imapd was waiting for my commands to enter: ... LOGIN "***user***" "***password***" ... SELECT "INBOX" ... SEARCH ALL UNDELETED ... SORT (DATE) US-ASCII ALL UNDELETED ... LOGOUT The trace is attached. Regards, Erwin Op 8 jun 2010, om 22:55 heeft Paul J Stevens het volgende geschreven: > >> There is a gap of around 3 seconds directly after I entered the . >> SEARCH ALL UNDELETED command. > > which would be explained by you taking 3 seconds to enter that command. > >> And there is a very large (almost 14 >> seconds) gap after reading the results from MySQL of the SELECT that >> is done for the SEARCH command. > > that one is tricky. Could you try again with trace_syslog=5, that would > give better indication where in the dbmail code the bottleneck is > occuring, or if it's in libmysqlclient. > > -- > ________________________________________________________________ > Paul Stevens paul at nfg.nl > NET FACILITIES GROUP GPG/PGP: 1024D/11F8CD31 > The Netherlands________________________________http://www.nfg.nl > _______________________________________________ > DBmail mailing list > [email protected] > http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail
Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Info:[imap] imap4.c,IMAPClientHandler(+191): COMMAND: [. SEARCH ALL UNDELETED] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[imapsession] dbmail-imapsession.c,build_args_array_ext(+2542): arg[0]: 'ALL' Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[imapsession] dbmail-imapsession.c,build_args_array_ext(+2542): arg[1]: 'UNDELETED' Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Info:[imap] imap4.c,IMAPClientHandler(+302): Executing command search... Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[db] db.c,db_acl_has_right(+4220): checking ACL [read_flag] for user [21702] on mailbox [27167] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[sql] dbmysql.c,db_query(+287): query [SELECT owner_idnr FROM dbmail_mailboxes WHERE mailbox_idnr = 27167] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[db] dbmodule.c,db_query(+145): last query took [0] seconds Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[db] db.c,db_acl_has_right(+4231): mailbox [27167] is owned by user [21702], giving all rights Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[sql] dbmysql.c,db_query(+287): query [SELECT message_idnr FROM dbmail_messages WHERE mailbox_idnr = 27167 AND status IN (0,1) ORDER BY message_idnr] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[db] dbmodule.c,db_query(+145): last query took [0] seconds Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,mailbox_build_uid_map(+184): ids [36], msn [36] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,append_search(+614): [0x1ba4ec90] leaf [1] type [1] field [] search [1:*] at depth [1] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_handle_search_args(+744): IST_UIDSET: 1:* Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,append_search(+614): [0x1ba55ef0] leaf [1] type [2] field [] search [1:*] at depth [1] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,append_search(+614): [0x1ba56fb0] leaf [1] type [3] field [] search [deleted_flag=0] at depth [1] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,dbmail_mailbox_build_imap_search(+1168): done [0] at idx [2] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,dbmail_mailbox_get_set(+1431): [1:*] uid [0] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[misc] misc.c,g_tree_merge(+1260): (0x1ba4df30) (0x1ba4dce0): a[0] [OR] b[36] -> a[36] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_do_search(+1621): [0x1ba4ec90] depth [1] type [1] rows [36] Jul 6 08:07:03 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,dbmail_mailbox_get_set(+1431): [1:*] uid [1] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[misc] misc.c,g_tree_merge(+1260): (0x1ba4dce0) (0x1ba50720): a[0] [OR] b[36] -> a[36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_do_search(+1621): [0x1ba55ef0] depth [2] type [2] rows [36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[sql] dbmysql.c,db_query(+287): query [SELECT message_idnr FROM dbmail_messages WHERE mailbox_idnr = 27167 AND status IN (0,1) AND deleted_flag=0 ORDER BY message_idnr] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[db] dbmodule.c,db_query(+145): last query took [0] seconds Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_do_search(+1621): [0x1ba56fb0] depth [2] type [3] rows [36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[misc] misc.c,g_tree_merge(+1260): (0x1ba4e800) (0x1ba4df30): a[36] [AND] b[36] -> a[36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_merge_search(+1698): [0x1ba4ec90] leaf [0] depth [1] type [1] found [36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[misc] misc.c,g_tree_merge(+1260): (0x1ba4e800) (0x1ba4dce0): a[36] [AND] b[36] -> a[36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_merge_search(+1698): [0x1ba55ef0] leaf [1] depth [2] type [2] found [36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[misc] misc.c,g_tree_merge(+1260): (0x1ba4e800) (0x1ba50720): a[36] [AND] b[36] -> a[36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,_merge_search(+1698): [0x1ba56fb0] leaf [1] depth [2] type [3] found [36] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[mailbox] dbmail-mailbox.c,dbmail_mailbox_search(+1730): found [36] ids Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[imapsession] dbmail-imapsession.c,dbmail_imap_session_printf(+1527): RESPONSE: [* SEARCH 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 ...] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Debug:[imapsession] dbmail-imapsession.c,dbmail_imap_session_printf(+1525): RESPONSE: [. OK SEARCH completed ] Jul 6 08:07:14 esx-nas dbmail/imap4d[16445]: Info:[imap] imap4.c,IMAPClientHandler(+321): Finished command search [0]
_______________________________________________ DBmail mailing list [email protected] http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail
