These are the commands that my Squirrelmail 1.4.5 server issues when connecting to dbmail-2.1.5:
A001 LOGIN "user" "password"
A002 SELECT "INBOX"
A003 EXPUNGE
A004 EXAMINE "INBOX"
A005 SELECT "INBOX"
A006 EXPUNGE
A007 EXPUNGE
A008 UID SORT (ARRIVAL) ISO-8859-1 ALL
A008 takes quite a bit of time to complete -- on the order of 4-5minutes
of CPU time on a PIII Xeon. The process itself is not large -- perhaps
20M RSS. Looking a bit at the call tree dbmail seems to be spending
ages of time in a mailbox *search*, which I'm not quite sure I understand.
Here's a typical stack trace when I attach with GDB. IT almost always
seems to be in IA__g_list_last (presumably chasing the pointer):
(gdb) bt
#0 0x40119295 in IA__g_list_last (list=0x80a73bc) at glist.c:629
#1 0x40118a69 in IA__g_list_append (list=0x8069a88, data=0x80a73c8)
at glist.c:251
#2 0x40196a5b in traverse_tree_keys (key=0x80a73c8, value=0x872f8f8,
l=0xbfffc4b0) at misc.c:1279
#3 0x40139b69 in g_tree_node_in_order (node=0x872f5d8,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:892
#4 0x40139ba3 in g_tree_node_in_order (node=0x872f588,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#5 0x40139b4c in g_tree_node_in_order (node=0x872f968,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#6 0x40139b4c in g_tree_node_in_order (node=0x872faa8,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#7 0x40139ba3 in g_tree_node_in_order (node=0x872f4e8,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#8 0x40139b4c in g_tree_node_in_order (node=0x8730068,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#9 0x40139ba3 in g_tree_node_in_order (node=0x872eca8,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#10 0x40139b4c in g_tree_node_in_order (node=0x87310e8,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#11 0x40139ba3 in g_tree_node_in_order (node=0x872c868,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#12 0x40139b4c in g_tree_node_in_order (node=0x8735968,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#13 0x40139b4c in g_tree_node_in_order (node=0x8747ea8,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#14 0x40139b4c in g_tree_node_in_order (node=0x876c928,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#15 0x40139ba3 in g_tree_node_in_order (node=0x8723428,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#16 0x40139ba3 in g_tree_node_in_order (node=0x8690d68,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#17 0x40139b4c in g_tree_node_in_order (node=0x87b5e28,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:889
#18 0x40139ba3 in g_tree_node_in_order (node=0x856b968,
traverse_func=0x40196a30 <traverse_tree_keys>, data=0xbfffc4b0)
at gtree.c:896
#19 0x40196ae7 in g_tree_keys (tree=0x80a73c8) at misc.c:1291
#20 0x401876f0 in dbmail_mailbox_get_set (self=0x807dbc8, sk=0x401a07f7)
at dbmail-mailbox.c:1292
#21 0x40187b62 in _do_search (node=0x807fefc, self=0x807dbc8)
at dbmail-mailbox.c:1404
#22 0x40125ab8 in g_node_traverse_pre_order (node=0x807fefc,
flags=G_TRAVERSE_LEAVES, func=0x40187af0 <_do_search>,
data=0x807dbc8)
at gnode.c:514
#23 0x40125a6f in g_node_traverse_pre_order (node=0x0,
flags=G_TRAVERSE_ALL,
func=0x40187af0 <_do_search>, data=0x807dbc8) at gnode.c:510
#24 0x40187e49 in dbmail_mailbox_search (self=0x807dbc8)
at dbmail-mailbox.c:1497
#25 0x08052855 in sorted_search (self=0x80705b8, sorted=1)
at imapcommands.c:1434
#26 0x0805295a in _ic_sort (self=0x80a73c8) at imapcommands.c:1465
#27 0x08053f27 in _ic_uid (self=0x80705b8) at imapcommands.c:2143
#28 0x0804d99d in IMAPClientHandler (ci=0x80a73c8) at imap4.c:318
#29 0x40198c5f in PerformChildTask (info=0x401b0940) at
serverchild.c:305
#30 0x40198824 in CreateChild (info=0x80a73c8) at serverchild.c:191
#31 0x4019a05c in manage_spare_children () at pool.c:482
#32 0x40197ba0 in StartServer (conf=0xbffff060) at server.c:141
#33 0x40197df5 in server_run (conf=0xbffff060) at server.c:177
---Type <return> to continue, or q <return> to quit---
#34 0x080551f1 in main (argc=1, argv=0xbffff060) at imapd.c:133
I compiled dbmail and glib with profiling and gprof shows almost all
time being spent in IA__g_list_last. (Note the CPU time reported by
time was 277.17s -- the rest is probably in glibc and mysql libs..)
time seconds seconds calls s/call s/call name
99.35 272.99 272.99 344704 0.00 0.00 IA__g_list_last
0.20 273.54 0.55 18702183 0.00 0.00 ucmp
0.10 273.82 0.28 344681 0.00 0.00 g_tree_node_insert
0.06 273.99 0.17 860545 0.00 0.00 g_tree_node_lookup
0.05 274.12 0.13 344771 0.00 0.00 _g_list_alloc
0.03 274.20 0.08 14 0.01 0.01 db_getmailbox
(full profile log attached)
I'm not sure if what I'm seeing is unexpected, unsusal, or particularly
pathological...
Any thoughts? Yes, I know 80k-messages is obscene, but I'm curious if
it's possible in 2.1.
Matt
profile.log.gz
Description: Binary data
