[Dovecot] imap process consuming 100% CPU (Dovecot 1.0.3)

Jackie Hunt jackie at yuma.acns.colostate.edu
Thu Nov 15 19:55:32 EET 2007


> 
> 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


More information about the dovecot mailing list