[Dovecot] imap process consuming 100% CPU (Dovecot 1.0.3)
Stewart Dean
sdean at bard.edu
Mon Nov 19 23:12:14 EET 2007
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:
>>>>>
>>>>>
>>>> Fixed: http://hg.dovecot.org/dovecot-1.0/rev/8e86137a04fb
>>>>
>>>>
>>> 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 at 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) cont
>>>
>>> execution completed
>>> (dbx) quit
>>> $
>>>
>>>
>> --
>> ====
>> Stewart Dean, Unix System Admin, Henderson Computer Resources
>> Center of Bard College, Annandale-on-Hudson, New York 12504
>> sdean at 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 at colostate.edu
>
--
====
Stewart Dean, Unix System Admin, Henderson Computer Resources
Center of Bard College, Annandale-on-Hudson, New York 12504
sdean at bard.edu voice: 845-758-7475, fax: 845-758-7035
More information about the dovecot
mailing list