Hi Guys
Still having an issue with slow imap queries via overlook
(its a
squirrelmail base with changes in gui, we've also tested
squirrelmail with
same results),
We're getting *very* slow queries on some mailboxes below
ive provided a
level 5 trace log
This client has 14mb of mail which is about 280 emails or
so
Can anyone shed some light on this?
The database is running on a dedicated server with very
little load on it
and im testing this from a spare failover webserver with the
same results as
the live webserver so im confident its not an I/O error
machines are also on
a bonded gigabit connection to eachother.
I saw a bug filed for a similar issue, is this still
outstanding? Bug id
579, i wonder if its related?
Not sure if you can see anything obvious from those
tracelogs, if anyone has
any ideas on how to fix this please let me know!
Regards
Jon
Jun 27 20:22:52 webmail-1 dbmail/imap4d[4840]: Debug:[misc]
misc.c,g_tree_merge(+1267): (0x808aad8) (0x8087768): a[0]
[OR] b[266] ->
a[266]
Jun 27 20:22:52 webmail-1 dbmail/imap4d[4840]:
Debug:[mailbox]
dbmail-mailbox.c,_do_search(+1569): [0x809ff00] depth [1]
type [2] rows
[266]
Jun 27 20:22:52 webmail-1 dbmail/imap4d[4840]:
Debug:[mailbox]
dbmail-mailbox.c,dbmail_mailbox_get_set(+1387): [1 ] uid [1]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Info:[serverchild]
serverchild.c,select_and_accept(+252): received connection
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Info:[serverchild]
serverchild.c,select_and_accept(+275): connection accepted
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Message:[serverchild]
serverchild.c,PerformChildTask(+341): incoming connection
from [127.0.0.1]
by pid [4839]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[serverchild]
serverchild.c,PerformChildTask(+366): client info init
complete, calling
client handler
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [* OK
dbmail imap (protocol version 4r1) server 2.2 ready to run^M
]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+175): COMMAND: [A0001 LOGIN
"addiscombe.addiscombe.org" "monty1"]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[0]:
'addiscombe.addiscombe.org'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[1]:
'monty1'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+288): Executing command login...
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_handle_auth(+1554):
trying to
validate user [addiscombe.addiscombe.org], pass [XXXX]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT userid FROM
dbmail_usermap WHERE 1 =
2]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_use_usermap(+167): enabling usermap lookups
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_usermap_resolve(+4536): checking userid
[addiscombe.addiscombe.org]
in usermap
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_usermap_resolve(+4547): client on inet socket
[inet:127.0.0.1:143]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT login, sock_allow,
sock_deny, userid
FROM dbmail_usermap WHERE login in
('addiscombe.addiscombe.org','ANY') ORDER
BY sock_allow, sock_deny]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_usermap_resolve(+4573): login
[addiscombe.addiscombe.org] not found
in usermap
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT user_idnr FROM
dbmail_users WHERE
lower(userid) = lower('addiscombe.addiscombe.org')]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT user_idnr, passwd,
encryption_type
FROM dbmail_users WHERE user_idnr = 2581]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[auth]
authsql.c,auth_validate(+401): validating using plaintext
passwords
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [UPDATE dbmail_users SET
last_login =
'2007-06-27 20:23:08' WHERE user_idnr = 2581]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Message:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_handle_auth(+1559):
user (id:2581,
name addiscombe.addiscombe.org) tries login
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Message:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_handle_auth(+1580):
user (id 2581,
name addiscombe.addiscombe.org) login accepted
Jun 27 20:23:08 webmail-1 in.imapproxyd[3403]: LOGIN:
'"addiscombe.addiscombe.org"' (127.0.0.1:57553) on
new sd [11]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [A0001 OK
LOGIN completed^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+307): Finished command login [0]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+175): COMMAND: [A002 CAPABILITY]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+288): Executing command
capability...
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1452):
RESPONSE: [*
CAPABILITY IMAP4 IMAP4rev1 AUTH=LOGIN ACL NAMESPACE CHILDREN
SORT QUOTA
THREAD=ORDEREDSUBJECT UNS...]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [A002 OK
CAPABILITY completed^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+307): Finished command capability
[0]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+175): COMMAND: [A003 NAMESPACE]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+288): Executing command
namespace...
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [*
NAMESPACE (("" "/"))
(("#Users" "/")) (("#Public"
"/"))^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [A003 OK
NAMESPACE complete^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+307): Finished command namespace
[0]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+175): COMMAND: [C64 UNSELECT]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+288): Executing command
unselect...
Jun 27 20:23:08 webmail-1 in.imapproxyd[3403]: LOGOUT:
'"addiscombe.addiscombe.org"' from server sd [11]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [C64 BAD
UNSELECT command received in invalid state^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+307): Finished command unselect
[1]
Jun 27 20:23:08 webmail-1 in.imapproxyd[3403]: LOGIN:
'"addiscombe.addiscombe.org"' (127.0.0.1:57555) on
existing sd [11]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+175): COMMAND: [A002 STATUS
"INBOX" (MESSAGES
UNSEEN RECENT)]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[0]:
'INBOX'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[1]:
'('
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[2]:
'MESSAGES'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[3]:
'UNSEEN'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[4]:
'RECENT'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[5]:
')'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+288): Executing command
status...
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_findmailbox(+2519): looking for mailbox with FQN
[INBOX].
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT mailbox_idnr FROM
dbmail_mailboxes
WHERE name LIKE 'INBOX' AND owner_idnr=2581]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_acl_has_right(+4064): checking ACL [read_flag] for
user [2581] on
mailbox [4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT owner_idnr FROM
dbmail_mailboxes
WHERE mailbox_idnr = 4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_acl_has_right(+4075): mailbox [4945] is owned by
user [2581], giving
all rights
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT
permission,seen_flag,answered_flag,deleted_flag,flagged_flag
,recent_flag,dra
ft_flag FROM dbmail_mailboxes WHERE mailbox_idnr = 4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT 'a',COUNT(*) FROM
dbmail_messages
WHERE mailbox_idnr=4945 AND (status < 2) UNION SELECT
'b',COUNT(*) FROM
dbmail_messages WHERE mailbox_idnr=4945 AND (status < 2)
AND seen_flag=1
UNION SELECT 'c',COUNT(*) FROM dbmail_messages WHERE
mailbox_idnr=4945 AND
(status < 2) AND recent_flag=1]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT message_idnr+1 FROM
dbmail_messages
WHERE mailbox_idnr=4945 ORDER BY message_idnr DESC LIMIT 1]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [* STATUS
"INBOX" (MESSAGES 266 UNSEEN 170 RECENT 0)^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [A002 OK
STATUS completed^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+307): Finished command status
[0]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+175): COMMAND: [A003 SELECT
"INBOX"]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,build_args_array_ext(+2398): arg[0]:
'INBOX'
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Info:[imap]
imap4.c,IMAPClientHandler(+288): Executing command
select...
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_findmailbox(+2519): looking for mailbox with FQN
[INBOX].
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT mailbox_idnr FROM
dbmail_mailboxes
WHERE name LIKE 'INBOX' AND owner_idnr=2581]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_acl_has_right(+4064): checking ACL [read_flag] for
user [2581] on
mailbox [4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT owner_idnr FROM
dbmail_mailboxes
WHERE mailbox_idnr = 4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[db]
db.c,db_acl_has_right(+4075): mailbox [4945] is owned by
user [2581], giving
all rights
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT no_select FROM
dbmail_mailboxes
WHERE mailbox_idnr = 4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT
permission,seen_flag,answered_flag,deleted_flag,flagged_flag
,recent_flag,dra
ft_flag FROM dbmail_mailboxes WHERE mailbox_idnr = 4945]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT 'a',COUNT(*) FROM
dbmail_messages
WHERE mailbox_idnr=4945 AND (status < 2) UNION SELECT
'b',COUNT(*) FROM
dbmail_messages WHERE mailbox_idnr=4945 AND (status < 2)
AND seen_flag=1
UNION SELECT 'c',COUNT(*) FROM dbmail_messages WHERE
mailbox_idnr=4945 AND
(status < 2) AND recent_flag=1]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT message_idnr+1 FROM
dbmail_messages
WHERE mailbox_idnr=4945 ORDER BY message_idnr DESC LIMIT 1]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT message_idnr FROM
dbmail_messages
WHERE mailbox_idnr = 4945 AND status IN (0,1) ORDER BY
message_idnr]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[mailbox]
dbmail-mailbox.c,mailbox_build_uid_map(+180): ids [266], msn
[266]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]: Debug:[sql]
dbmysql.c,db_query(+290): query [SELECT seen_flag,
answered_flag,
deleted_flag, flagged_flag, draft_flag, recent_flag,
DATE_FORMAT(internal_date, '%Y-%m-%d %T'), rfcsize,
message_idnr FROM
dbmail_messages msg, dbmail_physmessage pm WHERE pm.id =
msg.physmessage_id
AND message_idnr BETWEEN 21724194 AND 66992769 AND
mailbox_idnr = 4945 AND
status IN (0,1) ORDER BY message_idnr ASC]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [* 266
EXISTS^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [* 0
RECENT^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [* FLAGS
(Seen Answered Deleted Flagged Draft)^M ]
Jun 27 20:23:08 webmail-1 dbmail/imap4d[4839]:
Debug:[imapsession]
dbmail-imapsession.c,dbmail_imap_session_printf(+1450):
RESPONSE: [* OK
[PERMANENTFLAGS (Seen Answered Deleted Flagged
Draft)]^M ]
Regards
Jon Duggan
Nuco Technologies Ltd
jon host-it.co.uk
Tel. 0870 165 1300
_______________________________________________
DBmail mailing list
DBmail dbmail.org
htt
ps://mailman.fastxs.nl/mailman/listinfo/dbmail
|