Re: [Dovecot] imap process consuming 100% CPU (Dovecot 1.0.3)
Is this behavior cured, or do you continue to see it?
No, the behavior isn't cured. We still continue to see it with various clients. I have posted a couple of truss outputs, but so far no resolution.
Sorry for the slow response. I've been "fighting other fires".
Jackie
Jackie Hunt wrote:
On Mon, 2007-09-03 at 12:37 +0200, Robert Tomanek wrote:
Hi,
Sunday, September 2, 2007, 22:42:37, you wrote:
0x0806049d in imap_sync_more (ctx=3D0x80d9770) at imap-sync.c:104 104 if (ctx->seq =3D=3D 0) {
A short follow-up on this, looks like an infinite loop to me, unless some threading magic is supposed to happen here:
We also are seeing imap processes consuming 100% CPU. We have installed Dovecot v1.0.5 and still see the problem. I have a user who can pretty reliably reproduce the problem. It occurs each morning after the imap connection has been idling all night. The user is running Thunderbird 2.0.0.6 (I think) on Solaris. On the client side, he see an hourglass that never goes away, has to shut down Thunderbird.
Below is a log, which shows how the CPU is being used (the ps commands are done one right after another) and a dbx trace of the state of the imap process. I'm hoping that's enough info to figure out what's happening.
Thanks much, Jackie
Jackie Hunt
ACNS Voice: (970) 663-3789
Colorado State University FAX: (970) 491-1958 Fort Collins, CO 80523 Email: jackie.hunt@colostate.edu$ ps -ef | grep -i xxxxxx | grep imap xxxxxx 43004 92942 74 07:15:33 - 38:54 imap $ ps -ef | grep -i xxxxxx | grep imap xxxxxx 43004 92942 81 07:15:33 - 38:58 imap $ ps -ef | grep -i xxxxxx | grep imap xxxxxx 43004 92942 120 07:15:33 - 39:01 imap $ dbx -a 43004 Waiting to attach to process 43004 ... Successfully attached to imap. warning: Directory containing imap could not be determined. Apply 'use' command to initialize source path.
Type 'help' for help. reading symbolic information ... stopped in pread at 0xd01f06cc 0xd01f06cc (pread+0x30) 80410014 lwz r2,0x14(r1) (dbx) step stopped in istream-file._read at line 120 in file "" could not read "istream-file.c" (dbx) use src lib src/lib src/lib-storage/index/mbox src/lib-mail src/lib-storage/index src/lib-storage src/imap src/imap-login (dbx) use src lib src/lib src/lib-storage/index/mbox src/lib-mail src/lib-storage/index src/lib-storage src/imap src/imap-login (dbx) where istream-file._read(stream = 0x200274a8), line 120 in "istream-file.c" i_stream_read(stream = 0x200274cc), line 58 in "istream.c" istream-raw-mbox._read(stream = 0x20028ab8), line 160 in "istream-raw-mbox.c" i_stream_read(stream = 0x20028adc), line 58 in "istream.c" istream-limit._read(stream = 0x20031458), line 56 in "istream-limit.c" i_stream_read(stream = 0x2003147c), line 58 in "istream.c" istream-header-filter._read(stream = 0x2004aa98), line 234 in "istream-header-filter.c" i_stream_read(stream = 0x2004aabc), line 58 in "istream.c" i_stream_read_data(stream = 0x2004aabc, data = 0x2ff22630, size = 0x2ff22638, threshold = 1), line 250 in "istream.c" message_get_body_size(input = 0x2004aabc, body = 0x2002827c, has_nuls = (nil)), line 107 in "message-size.c" index_mail_init_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 502 in "index-mail.c" mbox_mail_get_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 206 in "mbox-mail.c" mail_get_stream(mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 107 in "mail.c" imap-fetch-body.fetch_body(ctx = 0x200205e0, mail = 0x200281a8, context = 0x20020858), line 331 in "imap-fetch-body.c" imap_fetch(ctx = 0x200205e0), line 291 in "imap-fetch.c" cmd_fetch(cmd = 0x2001e35c), line 163 in "cmd-fetch.c" cmd_uid(cmd = 0x2001e35c), line 19 in "cmd-uid.c" client_handle_input(cmd = 0x2001e35c), line 344 in "client.c" client_handle_input(cmd = 0x2001e35c), line 398 in "client.c" _client_input(context = 0x2001e318), line 441 in "client.c" io_loop_handler_run(ioloop = 0x2001d0e8), line 199 in "ioloop-poll.c" io_loop_run(ioloop = 0x2001d0e8), line 329 in "ioloop.c" main(argc = 1, argv = 0x2ff22b50, envp = 0x2ff22b58), line 290 in "main.c" (dbx) list 58 return _stream->read(_stream); 59 } 60
61 void i_stream_skip(struct istream *stream, uoff_t count) 62 { 63 struct _istream *_stream = stream->real_stream; 64 size_t data_size; 65
66 data_size = _stream->pos - _stream->skip; 67 if (count <= data_size) { (dbx) dump i_stream_read(stream = 0x2003147c), line 58 in "istream.c" _stream = 0x20031458 (dbx) up istream-header-filter._read(stream = 0x2004aa98), line 234 in "istream-header-filter.c" (dbx) list 234 if ((ret = i_stream_read(mstream->input)) == -2) { 235 if (stream->skip == 0) 236 return -2; 237 } 238 stream->istream.stream_errno = mstream->input->stream_errno; 239 stream->istream.eof = mstream->input->eof; 240 stream->buffer = i_stream_get_data(mstream->input, &pos); 241 } else { 242 ret = 0; 243 } (dbx) dump istream-header-filter._read(stream = 0x2004aa98), line 234 in "istream-header-filter.c" mstream = 0x2004aa98 ret = 4094 pos = 1 (dbx) up i_stream_read(stream = 0x2004aabc), line 58 in "istream.c" (dbx) list 58 return _stream->read(_stream); 59 } 60
61 void i_stream_skip(struct istream *stream, uoff_t count) 62 { 63 struct _istream *_stream = stream->real_stream; 64 size_t data_size; 65
66 data_size = _stream->pos - _stream->skip; 67 if (count <= data_size) { (dbx) dump i_stream_read(stream = 0x2004aabc), line 58 in "istream.c" _stream = 0x2004aa98 (dbx) up i_stream_read_data(stream = 0x2004aabc, data = 0x2ff22630, size = 0x2ff22638, threshold = 1), line 250 in "istream.c" (dbx) list 250 ret = i_stream_read(stream); 251 if (ret > 0) 252 read_more = TRUE; 253 } while (ret > 0); 254
255 *data = i_stream_get_data(stream, size); 256 return ret == -2 ? -2 : 257 (read_more || ret == 0 ? 0 : -1); 258 } 259
(dbx) dump i_stream_read_data(stream = 0x2004aabc, data = 0x2ff22630, size = 0x2ff22638, threshold = 1), line 250 in "istream.c" read_more = 0 ret = 0 (dbx) up message_get_body_size(input = 0x2004aabc, body = 0x2002827c, has_nuls = (nil)), line 107 in "message-size.c" (dbx) list 107 } while (i_stream_read_data(input, &msg, &size, 1) > 0); 108
109 i_stream_skip(input, 1); 110 body->physical_size++; 111
112 body->virtual_size = body->physical_size + missing_cr_count; 113 i_assert(body->virtual_size >= body->physical_size); 114 } 115
116 void message_size_add(struct message_size *dest, (dbx) dump message_get_body_size(input = 0x2004aabc, body = 0x2002827c, has_nuls = (nil)), line 107 in "message-size.c" last_cr = 0 missing_cr_count = 83389 msg = "dd" i = 4095 size = 1 (dbx) up index_mail_init_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 502 in "index-mail.c" (dbx) list 502 message_get_body_size(data->stream, 503 &data->body_size, NULL); 504 data->body_size_set = TRUE; 505 } 506 } 507
508 *body_size = data->body_size; 509 } 510
511 if (data->hdr_size_set && data->body_size_set) { (dbx) dump index_mail_init_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 502 in "index-mail.c" data = 0x2002820c mail = 0x200281a8 (dbx) up mbox_mail_get_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 206 in "mbox-mail.c" (dbx) list 206 return index_mail_init_stream(mail, hdr_size, body_size); 207 } 208
209 struct mail_vfuncs mbox_mail_vfuncs = { 210 index_mail_free, 211 index_mail_set_seq, 212
213 index_mail_get_flags, 214 index_mail_get_keywords, 215 index_mail_get_parts, (dbx) dump mbox_mail_get_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 206 in "mbox-mail.c" raw_stream = 0x2ff22780 mbox = 0x20024a98 data = 0x2002820c mail = 0x200281a8 offset = 804398928 (dbx) up mail_get_stream(mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 107 in "mail.c" (dbx) list 107 return p->v.get_stream(mail, hdr_size, body_size); 108 } 109
110 const char *mail_get_special(struct mail *mail, enum mail_fetch_field field) 111 { 112 struct mail_private *p = (struct mail_private *)mail; 113
114 return p->v.get_special(mail, field); 115 } 116
(dbx) dump mail_get_stream(mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 107 in "mail.c" p = 0x200281a8 (dbx) up imap-fetch-body.fetch_body(ctx = 0x200205e0, mail = 0x200281a8, context = 0x20020858), line 331 in "imap-fetch-body.c" (dbx) list 331 body->section[0] == 'H' ? NULL : &body_size); 332 if (ctx->cur_input == NULL) 333 return -1; 334
335 i_stream_ref(ctx->cur_input); 336 ctx->update_partial = TRUE; 337
338 switch (body->section[0]) { 339 case '\0': 340 /* BODY[] - fetch everything */ (dbx) dump imap-fetch-body.fetch_body(ctx = 0x200205e0, mail = 0x200281a8, context = 0x20020858), line 331 in "imap-fetch-body.c" fetch_size = 0x20011dd8 hdr_size = (physical_size = 843, virtual_size = 843, lines = 15) body = 0x20020858 body_size = (physical_size = 804398512, virtual_size = 12, lines = 0) (dbx) up imap_fetch(ctx = 0x200205e0), line 291 in "imap-fetch.c" (dbx) list 291 ret = handlers[ctx->cur_handler]. 292 handler(ctx, ctx->cur_mail, 293 handlers[ctx->cur_handler].context); 294 t_pop(); 295
296 if (ret == 0) 297 return 0; 298
299 if (ret < 0) { 300 if (ctx->cur_mail->expunged) { (dbx) dump imap_fetch(ctx = 0x200205e0), line 291 in "imap-fetch.c" handlers = 0x200206f8 count = 3 ret = 1 (dbx) up cmd_fetch(cmd = 0x2001e35c), line 163 in "cmd-fetch.c" (dbx) list 163 if ((ret = imap_fetch(ctx)) == 0) { 164 /* unfinished */ 165 client->command_pending = TRUE; 166 cmd->func = cmd_fetch_continue; 167 cmd->context = ctx; 168 return FALSE; 169 } 170 if (ret < 0) 171 ctx->failed = TRUE; 172
(dbx) dump cmd_fetch(cmd = 0x2001e35c), line 163 in "cmd-fetch.c" messageset = "11988" search_arg = 0x200205a8 ctx = 0x200205e0 args = 0x2001e590 ret = 536954712 client = 0x2001e318 (dbx) up cmd_uid(cmd = 0x2001e35c), line 19 in "cmd-uid.c" (dbx) list 19 return cmd->func(cmd); 20 } else { 21 client_send_tagline(cmd, t_strconcat( 22 "BAD Unknown UID command ", cmd_name, NULL)); 23 return TRUE; 24 } 25 } (dbx) dump cmd_uid(cmd = 0x2001e35c), line 19 in "cmd-uid.c" cmd_name = "fetch" (dbx) up client_handle_input(cmd = 0x2001e35c), line 344 in "client.c" (dbx) list 344 if (cmd->func(cmd) || cmd->param_error) { 345 /* command execution was finished */ 346 if (!cmd->param_error) 347 client->bad_counter = 0; 348 _client_reset_command(client); 349 return TRUE; 350 } 351
352 /* unfinished */ 353 if (client->command_pending) (dbx) dump client_handle_input(cmd = 0x2001e35c), line 344 in "client.c" client = 0x2001e318 (dbx) up client_handle_input(cmd = 0x2001e35c), line 398 in "client.c" (dbx) list 398 client_handle_input(cmd); 399 } 400
401 return TRUE; 402 } 403
404 void _client_input(void *context) 405 { 406 struct client *client = context; 407 struct client_command_context *cmd = &client->cmd; (dbx) dump client_handle_input(cmd = 0x2001e35c), line 398 in "client.c" client = 0x2001e318 (dbx) up _client_input(context = 0x2001e318), line 441 in "client.c" (dbx) list 441 ret = client_handle_input(cmd); 442 t_pop(); 443 } while (ret && !client->disconnected); 444 o_stream_uncork(client->output); 445 client->handling_input = FALSE; 446
447 if (client->command_pending) 448 client->input_pending = TRUE; 449
450 if (client->output->closed) (dbx) dump _client_input(context = 0x2001e318), line 441 in "client.c" ret = 2 cmd = 0x2001e35c client = 0x2001e318 (dbx) up io_loop_handler_run(ioloop = 0x2001d0e8), line 199 in "ioloop-poll.c" (dbx) list 199 io->callback(io->context); 200 if (t_pop() != t_id) { 201 i_panic("Leaked a t_pop() call in " 202 "I/O handler %p", 203 (void *)io->callback); 204 } 205 } 206 } 207 } 208 } (dbx) dump io_loop_handler_run(ioloop = 0x2001d0e8), line 199 in "ioloop-poll.c" t_id = 2 tv = (tv_sec = 1, tv_usec = 54083) msecs = 1055 pollfd = 0x2001d148 ctx = 0x2001d118 ret = 0 io = 0x2001e4e8 call = 1 (dbx) up io_loop_run(ioloop = 0x2001d0e8), line 329 in "ioloop.c" (dbx) list 329 io_loop_handler_run(ioloop); 330 } 331
332 void io_loop_stop(struct ioloop *ioloop) 333 { 334 ioloop->running = FALSE; 335 } 336
337 void io_loop_set_running(struct ioloop *ioloop) 338 { (dbx) dump io_loop_run(ioloop = 0x2001d0e8), line 329 in "ioloop.c" (dbx) up main(argc = 1, argv = 0x2ff22b50, envp = 0x2ff22b58), line 290 in "main.c" (dbx) list 290 io_loop_run(ioloop); 291 main_deinit(); 292
293 io_loop_destroy(&ioloop); 294 lib_deinit(); 295
296 return 0; 297 } (dbx) dump main(argc = 1, argv = 0x2ff22b50, envp = 0x2ff22b58), line 290 in "main.c" (dbx) up __start() at 0x100001d8 (dbx) list no source file (dbx) dump __start() at 0x100001d8 (dbx) contexecution completed (dbx) quit $
--
Stewart Dean, Unix System Admin, Henderson Computer Resources Center of Bard College, Annandale-on-Hudson, New York 12504
sdean@bard.edu voice: 845-758-7475, fax: 845-758-7035
Jackie Hunt
ACNS Voice: (970) 663-3789
Colorado State University FAX: (970) 491-1958
Fort Collins, CO 80523 Email: jackie.hunt@colostate.edu
I think I'm seeing this with TBird and 1.0.7...with my own account! It may even be a Tbird problem. I have a 4way mail server, so when I get 25%, it's 100% of one processor. I tried killing the imap process on the server and it can back at 9% and climbed quickly back up to 25%. It wasn't until I shutdown my TBird session that a clean imap session was established.
Jackie Hunt wrote:
Is this behavior cured, or do you continue to see it?
No, the behavior isn't cured. We still continue to see it with various clients. I have posted a couple of truss outputs, but so far no resolution.
Sorry for the slow response. I've been "fighting other fires".
Jackie
Jackie Hunt wrote:
On Mon, 2007-09-03 at 12:37 +0200, Robert Tomanek wrote:
Hi,
Sunday, September 2, 2007, 22:42:37, you wrote:
> 0x0806049d in imap_sync_more (ctx=3D0x80d9770) at imap-sync.c:104 > 104 if (ctx->seq =3D=3D 0) { >
>
A short follow-up on this, looks like an infinite loop to me, unless some threading magic is supposed to happen here:We also are seeing imap processes consuming 100% CPU. We have installed Dovecot v1.0.5 and still see the problem. I have a user who can pretty reliably reproduce the problem. It occurs each morning after the imap connection has been idling all night. The user is running Thunderbird 2.0.0.6 (I think) on Solaris. On the client side, he see an hourglass that never goes away, has to shut down Thunderbird.
Below is a log, which shows how the CPU is being used (the ps commands are done one right after another) and a dbx trace of the state of the imap process. I'm hoping that's enough info to figure out what's happening.
Thanks much, Jackie
Jackie Hunt
ACNS Voice: (970) 663-3789
Colorado State University FAX: (970) 491-1958 Fort Collins, CO 80523 Email: jackie.hunt@colostate.edu$ ps -ef | grep -i xxxxxx | grep imap xxxxxx 43004 92942 74 07:15:33 - 38:54 imap $ ps -ef | grep -i xxxxxx | grep imap xxxxxx 43004 92942 81 07:15:33 - 38:58 imap $ ps -ef | grep -i xxxxxx | grep imap xxxxxx 43004 92942 120 07:15:33 - 39:01 imap $ dbx -a 43004 Waiting to attach to process 43004 ... Successfully attached to imap. warning: Directory containing imap could not be determined. Apply 'use' command to initialize source path.
Type 'help' for help. reading symbolic information ... stopped in pread at 0xd01f06cc 0xd01f06cc (pread+0x30) 80410014 lwz r2,0x14(r1) (dbx) step stopped in istream-file._read at line 120 in file "" could not read "istream-file.c" (dbx) use src lib src/lib src/lib-storage/index/mbox src/lib-mail src/lib-storage/index src/lib-storage src/imap src/imap-login (dbx) use src lib src/lib src/lib-storage/index/mbox src/lib-mail src/lib-storage/index src/lib-storage src/imap src/imap-login (dbx) where istream-file._read(stream = 0x200274a8), line 120 in "istream-file.c" i_stream_read(stream = 0x200274cc), line 58 in "istream.c" istream-raw-mbox._read(stream = 0x20028ab8), line 160 in "istream-raw-mbox.c" i_stream_read(stream = 0x20028adc), line 58 in "istream.c" istream-limit._read(stream = 0x20031458), line 56 in "istream-limit.c" i_stream_read(stream = 0x2003147c), line 58 in "istream.c" istream-header-filter._read(stream = 0x2004aa98), line 234 in "istream-header-filter.c" i_stream_read(stream = 0x2004aabc), line 58 in "istream.c" i_stream_read_data(stream = 0x2004aabc, data = 0x2ff22630, size = 0x2ff22638, threshold = 1), line 250 in "istream.c" message_get_body_size(input = 0x2004aabc, body = 0x2002827c, has_nuls = (nil)), line 107 in "message-size.c" index_mail_init_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 502 in "index-mail.c" mbox_mail_get_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 206 in "mbox-mail.c" mail_get_stream(mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 107 in "mail.c" imap-fetch-body.fetch_body(ctx = 0x200205e0, mail = 0x200281a8, context = 0x20020858), line 331 in "imap-fetch-body.c" imap_fetch(ctx = 0x200205e0), line 291 in "imap-fetch.c" cmd_fetch(cmd = 0x2001e35c), line 163 in "cmd-fetch.c" cmd_uid(cmd = 0x2001e35c), line 19 in "cmd-uid.c" client_handle_input(cmd = 0x2001e35c), line 344 in "client.c" client_handle_input(cmd = 0x2001e35c), line 398 in "client.c" _client_input(context = 0x2001e318), line 441 in "client.c" io_loop_handler_run(ioloop = 0x2001d0e8), line 199 in "ioloop-poll.c" io_loop_run(ioloop = 0x2001d0e8), line 329 in "ioloop.c" main(argc = 1, argv = 0x2ff22b50, envp = 0x2ff22b58), line 290 in "main.c" (dbx) list 58 return _stream->read(_stream); 59 } 60
61 void i_stream_skip(struct istream *stream, uoff_t count) 62 { 63 struct _istream *_stream = stream->real_stream; 64 size_t data_size; 65
66 data_size = _stream->pos - _stream->skip; 67 if (count <= data_size) { (dbx) dump i_stream_read(stream = 0x2003147c), line 58 in "istream.c" _stream = 0x20031458 (dbx) up istream-header-filter._read(stream = 0x2004aa98), line 234 in "istream-header-filter.c" (dbx) list 234 if ((ret = i_stream_read(mstream->input)) == -2) { 235 if (stream->skip == 0) 236 return -2; 237 } 238 stream->istream.stream_errno = mstream->input->stream_errno; 239 stream->istream.eof = mstream->input->eof; 240 stream->buffer = i_stream_get_data(mstream->input, &pos); 241 } else { 242 ret = 0; 243 } (dbx) dump istream-header-filter._read(stream = 0x2004aa98), line 234 in "istream-header-filter.c" mstream = 0x2004aa98 ret = 4094 pos = 1 (dbx) up i_stream_read(stream = 0x2004aabc), line 58 in "istream.c" (dbx) list 58 return _stream->read(_stream); 59 } 60
61 void i_stream_skip(struct istream *stream, uoff_t count) 62 { 63 struct _istream *_stream = stream->real_stream; 64 size_t data_size; 65
66 data_size = _stream->pos - _stream->skip; 67 if (count <= data_size) { (dbx) dump i_stream_read(stream = 0x2004aabc), line 58 in "istream.c" _stream = 0x2004aa98 (dbx) up i_stream_read_data(stream = 0x2004aabc, data = 0x2ff22630, size = 0x2ff22638, threshold = 1), line 250 in "istream.c" (dbx) list 250 ret = i_stream_read(stream); 251 if (ret > 0) 252 read_more = TRUE; 253 } while (ret > 0); 254
255 *data = i_stream_get_data(stream, size); 256 return ret == -2 ? -2 : 257 (read_more || ret == 0 ? 0 : -1); 258 } 259
(dbx) dump i_stream_read_data(stream = 0x2004aabc, data = 0x2ff22630, size = 0x2ff22638, threshold = 1), line 250 in "istream.c" read_more = 0 ret = 0 (dbx) up message_get_body_size(input = 0x2004aabc, body = 0x2002827c, has_nuls = (nil)), line 107 in "message-size.c" (dbx) list 107 } while (i_stream_read_data(input, &msg, &size, 1) > 0); 108
109 i_stream_skip(input, 1); 110 body->physical_size++; 111
112 body->virtual_size = body->physical_size + missing_cr_count; 113 i_assert(body->virtual_size >= body->physical_size); 114 } 115
116 void message_size_add(struct message_size *dest, (dbx) dump message_get_body_size(input = 0x2004aabc, body = 0x2002827c, has_nuls = (nil)), line 107 in "message-size.c" last_cr = 0 missing_cr_count = 83389 msg = "dd" i = 4095 size = 1 (dbx) up index_mail_init_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 502 in "index-mail.c" (dbx) list 502 message_get_body_size(data->stream, 503 &data->body_size, NULL); 504 data->body_size_set = TRUE; 505 } 506 } 507
508 *body_size = data->body_size; 509 } 510
511 if (data->hdr_size_set && data->body_size_set) { (dbx) dump index_mail_init_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 502 in "index-mail.c" data = 0x2002820c mail = 0x200281a8 (dbx) up mbox_mail_get_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 206 in "mbox-mail.c" (dbx) list 206 return index_mail_init_stream(mail, hdr_size, body_size); 207 } 208
209 struct mail_vfuncs mbox_mail_vfuncs = { 210 index_mail_free, 211 index_mail_set_seq, 212
213 index_mail_get_flags, 214 index_mail_get_keywords, 215 index_mail_get_parts, (dbx) dump mbox_mail_get_stream(_mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 206 in "mbox-mail.c" raw_stream = 0x2ff22780 mbox = 0x20024a98 data = 0x2002820c mail = 0x200281a8 offset = 804398928 (dbx) up mail_get_stream(mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 107 in "mail.c" (dbx) list 107 return p->v.get_stream(mail, hdr_size, body_size); 108 } 109
110 const char *mail_get_special(struct mail *mail, enum mail_fetch_field field) 111 { 112 struct mail_private *p = (struct mail_private *)mail; 113
114 return p->v.get_special(mail, field); 115 } 116
(dbx) dump mail_get_stream(mail = 0x200281a8, hdr_size = 0x2ff227a8, body_size = 0x2ff227b8), line 107 in "mail.c" p = 0x200281a8 (dbx) up imap-fetch-body.fetch_body(ctx = 0x200205e0, mail = 0x200281a8, context = 0x20020858), line 331 in "imap-fetch-body.c" (dbx) list 331 body->section[0] == 'H' ? NULL : &body_size); 332 if (ctx->cur_input == NULL) 333 return -1; 334
335 i_stream_ref(ctx->cur_input); 336 ctx->update_partial = TRUE; 337
338 switch (body->section[0]) { 339 case '\0': 340 /* BODY[] - fetch everything */ (dbx) dump imap-fetch-body.fetch_body(ctx = 0x200205e0, mail = 0x200281a8, context = 0x20020858), line 331 in "imap-fetch-body.c" fetch_size = 0x20011dd8 hdr_size = (physical_size = 843, virtual_size = 843, lines = 15) body = 0x20020858 body_size = (physical_size = 804398512, virtual_size = 12, lines = 0) (dbx) up imap_fetch(ctx = 0x200205e0), line 291 in "imap-fetch.c" (dbx) list 291 ret = handlers[ctx->cur_handler]. 292 handler(ctx, ctx->cur_mail, 293 handlers[ctx->cur_handler].context); 294 t_pop(); 295
296 if (ret == 0) 297 return 0; 298
299 if (ret < 0) { 300 if (ctx->cur_mail->expunged) { (dbx) dump imap_fetch(ctx = 0x200205e0), line 291 in "imap-fetch.c" handlers = 0x200206f8 count = 3 ret = 1 (dbx) up cmd_fetch(cmd = 0x2001e35c), line 163 in "cmd-fetch.c" (dbx) list 163 if ((ret = imap_fetch(ctx)) == 0) { 164 /* unfinished */ 165 client->command_pending = TRUE; 166 cmd->func = cmd_fetch_continue; 167 cmd->context = ctx; 168 return FALSE; 169 } 170 if (ret < 0) 171 ctx->failed = TRUE; 172
(dbx) dump cmd_fetch(cmd = 0x2001e35c), line 163 in "cmd-fetch.c" messageset = "11988" search_arg = 0x200205a8 ctx = 0x200205e0 args = 0x2001e590 ret = 536954712 client = 0x2001e318 (dbx) up cmd_uid(cmd = 0x2001e35c), line 19 in "cmd-uid.c" (dbx) list 19 return cmd->func(cmd); 20 } else { 21 client_send_tagline(cmd, t_strconcat( 22 "BAD Unknown UID command ", cmd_name, NULL)); 23 return TRUE; 24 } 25 } (dbx) dump cmd_uid(cmd = 0x2001e35c), line 19 in "cmd-uid.c" cmd_name = "fetch" (dbx) up client_handle_input(cmd = 0x2001e35c), line 344 in "client.c" (dbx) list 344 if (cmd->func(cmd) || cmd->param_error) { 345 /* command execution was finished */ 346 if (!cmd->param_error) 347 client->bad_counter = 0; 348 _client_reset_command(client); 349 return TRUE; 350 } 351
352 /* unfinished */ 353 if (client->command_pending) (dbx) dump client_handle_input(cmd = 0x2001e35c), line 344 in "client.c" client = 0x2001e318 (dbx) up client_handle_input(cmd = 0x2001e35c), line 398 in "client.c" (dbx) list 398 client_handle_input(cmd); 399 } 400
401 return TRUE; 402 } 403
404 void _client_input(void *context) 405 { 406 struct client *client = context; 407 struct client_command_context *cmd = &client->cmd; (dbx) dump client_handle_input(cmd = 0x2001e35c), line 398 in "client.c" client = 0x2001e318 (dbx) up _client_input(context = 0x2001e318), line 441 in "client.c" (dbx) list 441 ret = client_handle_input(cmd); 442 t_pop(); 443 } while (ret && !client->disconnected); 444 o_stream_uncork(client->output); 445 client->handling_input = FALSE; 446
447 if (client->command_pending) 448 client->input_pending = TRUE; 449
450 if (client->output->closed) (dbx) dump _client_input(context = 0x2001e318), line 441 in "client.c" ret = 2 cmd = 0x2001e35c client = 0x2001e318 (dbx) up io_loop_handler_run(ioloop = 0x2001d0e8), line 199 in "ioloop-poll.c" (dbx) list 199 io->callback(io->context); 200 if (t_pop() != t_id) { 201 i_panic("Leaked a t_pop() call in " 202 "I/O handler %p", 203 (void *)io->callback); 204 } 205 } 206 } 207 } 208 } (dbx) dump io_loop_handler_run(ioloop = 0x2001d0e8), line 199 in "ioloop-poll.c" t_id = 2 tv = (tv_sec = 1, tv_usec = 54083) msecs = 1055 pollfd = 0x2001d148 ctx = 0x2001d118 ret = 0 io = 0x2001e4e8 call = 1 (dbx) up io_loop_run(ioloop = 0x2001d0e8), line 329 in "ioloop.c" (dbx) list 329 io_loop_handler_run(ioloop); 330 } 331
332 void io_loop_stop(struct ioloop *ioloop) 333 { 334 ioloop->running = FALSE; 335 } 336
337 void io_loop_set_running(struct ioloop *ioloop) 338 { (dbx) dump io_loop_run(ioloop = 0x2001d0e8), line 329 in "ioloop.c" (dbx) up main(argc = 1, argv = 0x2ff22b50, envp = 0x2ff22b58), line 290 in "main.c" (dbx) list 290 io_loop_run(ioloop); 291 main_deinit(); 292
293 io_loop_destroy(&ioloop); 294 lib_deinit(); 295
296 return 0; 297 } (dbx) dump main(argc = 1, argv = 0x2ff22b50, envp = 0x2ff22b58), line 290 in "main.c" (dbx) up __start() at 0x100001d8 (dbx) list no source file (dbx) dump __start() at 0x100001d8 (dbx) contexecution completed (dbx) quit $
--
Stewart Dean, Unix System Admin, Henderson Computer Resources Center of Bard College, Annandale-on-Hudson, New York 12504
sdean@bard.edu voice: 845-758-7475, fax: 845-758-7035Jackie Hunt
ACNS Voice: (970) 663-3789
Colorado State University FAX: (970) 491-1958 Fort Collins, CO 80523 Email: jackie.hunt@colostate.edu
--
Stewart Dean, Unix System Admin, Henderson Computer Resources
Center of Bard College, Annandale-on-Hudson, New York 12504
sdean@bard.edu voice: 845-758-7475, fax: 845-758-7035
On Mon, 2007-11-19 at 16:12 -0500, Stewart Dean wrote:
I think I'm seeing this with TBird and 1.0.7...with my own account! It may even be a Tbird problem. I have a 4way mail server, so when I get 25%, it's 100% of one processor. I tried killing the imap process on the server and it can back at 9% and climbed quickly back up to 25%. It wasn't until I shutdown my TBird session that a clean imap session was established.
You could truss the process or do something else to find out what Thunderbird and Dovecot are talking to each others. If shutting down Thunderbird dropped the load, it sounds like a bug in Thunderbird. Some clients have been known to keep requesting same data over and over again from the server in some situations. If I could see what the IMAP traffic looks like, I might be able to add a workaround to it.
:w On Mon, 2007-11-19 at 16:12 -0500, Stewart Dean wrote:
I think I'm seeing this with TBird and 1.0.7...with my own account! It may even be a Tbird problem. I have a 4way mail server, so when I get 25%, it's 100% of one processor. I tried killing the imap process on the server and it can back at 9% and climbed quickly back up to 25%. It wasn't until I shutdown my TBird session that a clean imap session was established.
You could truss the process or do something else to find out what Thunderbird and Dovecot are talking to each others. If shutting down Thunderbird dropped the load, it sounds like a bug in Thunderbird. Some clients have been known to keep requesting same data over and over again from the server in some situations. If I could see what the IMAP traffic looks like, I might be able to add a workaround to it.
What Stewart describes sounds exactly like what we are seeing. Killing the
imap process doesn't change anything, it requires the client to be shut down
to avoid using 100% CPU. We have a user who was seeing this every morning.
However, something has changed and he now sees it about every 7 to 10 days.
Another interesting note is that he didn't see the issue when we were
running U of Wash's imap server.
Thanks for the suggestion on the truss command, Timo:
"truss -d -rO -w1"
I'll definitely post my results when I have some.
Jackie
Jackie Hunt
ACNS Voice: (970) 663-3789
Colorado State University FAX: (970) 491-1958
Fort Collins, CO 80523 Email: jackie.hunt@colostate.edu
Thanks for the suggestion on the truss command, Timo:
"truss -d -rO -w1"
We have seen the imap process consuming 100% CPU again, and this time I was able to get a trace, but it's too long to post to the list. I've sent a copy to Timo. Let me know if anyone else would like a copy of it.
This user is running Thunderbird on Solaris, and has at least two IMAP connections open continuously, one to a UofW server running on Solaris (I think), the other to Dovecot running on AIX. He has problems with the Dovecot connection hanging on him each morning. Thunderbird shows an hourglass, but he gets not indication of what is happening. He has to shut down Thunderbird to get it working again. It's a bit ironic/humorous, but his UofW connection is fine in Thunderbird, and that's how he notifies me his Dovecot imap is hung up.
We are running Dovecot 1.0.5 on AIX.
Thanks for any help! Jackie
Jackie Hunt ACNS Voice: (970) 663-3789 Colorado State University FAX: (970) 491-1958
On Tue, 2007-11-27 at 11:38 -0700, Jackie Hunt wrote:
Thanks for the suggestion on the truss command, Timo:
"truss -d -rO -w1"
We have seen the imap process consuming 100% CPU again, and this time I was able to get a trace, but it's too long to post to the list. I've sent a copy to Timo. Let me know if anyone else would like a copy of it.
This user is running Thunderbird on Solaris, and has at least two IMAP connections open continuously, one to a UofW server running on Solaris (I think), the other to Dovecot running on AIX. He has problems with the Dovecot connection hanging on him each morning. Thunderbird shows an hourglass, but he gets not indication of what is happening. He has to shut down Thunderbird to get it working again. It's a bit ironic/humorous, but his UofW connection is fine in Thunderbird, and that's how he notifies me his Dovecot imap is hung up.
Problem was that it was reading a 50MB mail in 12kB blocks, and Dovecot wasn't handling that very well. Fixed:
http://hg.dovecot.org/dovecot-1.0/rev/0fba164c6ba6 http://hg.dovecot.org/dovecot-1.0/rev/edd95f9c6ba4
Problem was that it was reading a 50MB mail in 12kB blocks, and Dovecot wasn't handling that very well. Fixed:
http://hg.dovecot.org/dovecot-1.0/rev/0fba164c6ba6 http://hg.dovecot.org/dovecot-1.0/rev/edd95f9c6ba4
That's awesome! Thanks so much Timo, you always come through!
I'll install the fixes ASAP.
Jackie
Jackie Hunt
ACNS Voice: (970) 663-3789
Colorado State University FAX: (970) 491-1958
Fort Collins, CO 80523 Email: jackie.hunt@colostate.edu
On Wed, 2007-11-28 at 08:09 -0700, Jackie Hunt wrote:
Problem was that it was reading a 50MB mail in 12kB blocks, and Dovecot wasn't handling that very well. Fixed:
http://hg.dovecot.org/dovecot-1.0/rev/0fba164c6ba6 http://hg.dovecot.org/dovecot-1.0/rev/edd95f9c6ba4
That's awesome! Thanks so much Timo, you always come through!
I'll install the fixes ASAP.
Actually that didn't fix it completely for mbox. This should really fix it: http://hg.dovecot.org/dovecot-1.0/rev/212777918121
Thanks Timo, you da man!
I found this interesting...Finland has just come out tops again in the latest PISA evaluation of secondary school student science prowess as it has been for some years. The US, no surprise, comes out in the middle as Joe and Jill SixPack think that achievement in anything much less math and science (they're hard!) is for geeks. http://news.bbc.co.uk/1/hi/education/4073753.stm http://en.wikipedia.org/wiki/Programme_for_International_Student_Assessment Must be those long winters where there's nothing to do but study :)
Timo Sirainen wrote:
On Wed, 2007-11-28 at 08:09 -0700, Jackie Hunt wrote:
Problem was that it was reading a 50MB mail in 12kB blocks, and Dovecot wasn't handling that very well. Fixed:
http://hg.dovecot.org/dovecot-1.0/rev/0fba164c6ba6 http://hg.dovecot.org/dovecot-1.0/rev/edd95f9c6ba4
That's awesome! Thanks so much Timo, you always come through!
I'll install the fixes ASAP.Actually that didn't fix it completely for mbox. This should really fix it: http://hg.dovecot.org/dovecot-1.0/rev/212777918121
--
Stewart Dean, Unix System Admin, Henderson Computer Resources
Center of Bard College, Annandale-on-Hudson, New York 12504
sdean@bard.edu voice: 845-758-7475, fax: 845-758-7035
On Dec 4, 2007, at 9:09 AM, Stewart Dean wrote:
I found this interesting...Finland has just come out tops again in
the latest PISA evaluation of secondary school student science
prowess as it has been for some years. The US, no surprise, comes
out in the middle as Joe and Jill SixPack think that achievement in
anything much less math and science (they're hard!) is for geeks. http://news.bbc.co.uk/1/hi/education/4073753.stm http://en.wikipedia.org/wiki/ Programme_for_International_Student_Assessment Must be those long winters where there's nothing to do but study :)
Oh, don't get me started. I'm so sick of the BudLight-swilling,
NASCAR-watching, WalMart-loving morons that I'm about ready to go
find a deserted island somewhere.
-Dave-- Dave McGuire Port Charlotte, FL Farewell Ophelia, 9/22/1991 - 7/25/2007
participants (4)
-
Dave McGuire
-
Jackie Hunt
-
Stewart Dean
-
Timo Sirainen