Huge performance problem

[mtrojahn]

Hello,

I've been using the beta version for more than a year now, I think, and I never had any problems with it... Usually, I have around 200 simultaneous users browsing the webmail... Most of this people leave it open all day long, using it as their main mail client...

After upgrading to the new "stable" version I had numerous problems... After a while, a lot of apache's threads are using 100% CPU time... Sometimes I get an error on the webmail log about not being able to open files (max file descriptors reached)... And sometimes I get another error saying PHP used all memory available...

These errors are really bad things to happen on a production server... The server hosting the webmail gets unusable after a while... Not being possible to even start a ssh session to it... The DNS server that also runs on that same server stops works when that happens too...

So, after playing around on apache and php configurations with no success... I finally gave up and went back to the previous version which is now working perfectly all day long... The new version works for about 3 hours max...

Here's a few error examples I got with the new version (its not in order, just to illustrate the problem):
[19-Mar-2008 23:17:13] PHP Fatal error: Maximum execution time of 120 seconds exceeded in /var/www/localhost/vhosts/roundcube/program/lib/imap.inc on line 2369
[20-Mar-2008 14:44:13 -0300] DB Error: DB Error: no database selected Query: SELECT COUNT(contact_id) AS rows FROM contacts WHERE del<>1 AND  user_id='1244' [nativecode=2006 ** MySQL server has gone away] in /var/www/localhost/vhosts/roundcube/program/include/rcube_db.inc on line 520
[21-Mar-2008 17:39:07] PHP Warning: dl() [function.dl]: Not supported in multithreaded Web servers - use extension=fileinfo.so in your php.ini in /var/www/localhost/vhosts/roundcube/program/include/rcube_shared.inc on line 699
[21-Mar-2008 17:39:08 -0300] IMAP Error: Could not save message in Sent in /var/www/localhost/vhosts/roundcube/program/steps/mail/sendmail.inc on line 0
[21-Mar-2008 17:39:28] PHP Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 129761257 bytes) in /var/www/localhost/vhosts/roundcube/program/lib/imap.inc on line 2358


And here, the apache log when it kinda crashed during one of the times the server got slowed down:
Mar 20 20:29:54 nameserver apache2 invoked oom-killer: gfp_mask=0xa80d2, order=0, oomkilladj=0
Mar 20 20:29:54 nameserver [] [] [] [] [] [] [] [] [] [] [] =======================
Mar 20 20:29:54 nameserver Mem-info:
Mar 20 20:29:54 nameserver DMA per-cpu:
Mar 20 20:29:54 nameserver CPU  0: Hot: hi:  0, btch:  1 usd:  0  Cold: hi:  0, btch:  1 usd:  0
Mar 20 20:29:54 nameserver Normal per-cpu:
Mar 20 20:29:54 nameserver CPU  0: Hot: hi: 186, btch: 31 usd: 16  Cold: hi:  62, btch: 15 usd: 57
Mar 20 20:29:54 nameserver Active:46283 inactive:76848 dirty:0 writeback:0 unstable:0
Mar 20 20:29:54 nameserver free:1255 slab:2096 mapped:39 pagetables:585 bounce:0
Mar 20 20:29:54 nameserver DMA free:2056kB min:88kB low:108kB high:132kB active:5396kB inactive:5360kB present:16256kB pages_scanned:18338 all_unreclaimable? yes
Mar 20 20:29:55 nameserver lowmem_reserve[]: 0 492 492
Mar 20 20:29:55 nameserver Normal free:2964kB min:2792kB low:3488kB high:4188kB active:179736kB inactive:302032kB present:503924kB pages_scanned:905861 all_unreclaimable? yes
Mar 20 20:29:55 nameserver lowmem_reserve[]: 0 0 0
Mar 20 20:29:55 nameserver DMA: 2*4kB 0*8kB 0*16kB 2*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2056kB
Mar 20 20:29:55 nameserver Normal: 61*4kB 4*8kB 4*16kB 0*32kB 5*64kB 4*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2964kB
Mar 20 20:29:55 nameserver Swap cache: add 137283, delete 137280, find 5711/6808, race 0+0
Mar 20 20:29:55 nameserver Free swap = 0kB
Mar 20 20:29:55 nameserver Total swap = 497912kB
Mar 20 20:29:55 nameserver Free swap:      0kB
Mar 20 20:29:55 nameserver 131068 pages of RAM
Mar 20 20:29:55 nameserver 0 pages of HIGHMEM
Mar 20 20:29:55 nameserver 1969 reserved pages
Mar 20 20:29:55 nameserver 6508 pages shared
Mar 20 20:29:55 nameserver 3 pages swap cached
Mar 20 20:29:55 nameserver 0 pages dirty
Mar 20 20:29:55 nameserver 0 pages writeback
Mar 20 20:29:55 nameserver 39 pages mapped
Mar 20 20:29:55 nameserver 2096 pages slab
Mar 20 20:29:55 nameserver 585 pages pagetables
Mar 20 20:29:55 nameserver Out of memory: kill process 11272 (apache2) score 255908 or a child
Mar 20 20:29:55 nameserver Killed process 11273 (apache2)
Mar 20 20:29:55 nameserver apache2 invoked oom-killer: gfp_mask=0xa80d2, order=0, oomkilladj=0
Mar 20 20:29:55 nameserver [] [] [] [] [] [] [] [] [] [] =======================
Mar 20 20:29:55 nameserver Mem-info:
Mar 20 20:29:55 nameserver DMA per-cpu:
Mar 20 20:29:55 nameserver CPU  0: Hot: hi:  0, btch:  1 usd:  0  Cold: hi:  0, btch:  1 usd:  0
Mar 20 20:29:55 nameserver Normal per-cpu:
Mar 20 20:29:55 nameserver CPU  0: Hot: hi: 186, btch: 31 usd: 16  Cold: hi:  62, btch: 15 usd: 57
Mar 20 20:29:55 nameserver Active:43405 inactive:79763 dirty:0 writeback:0 unstable:0
Mar 20 20:29:55 nameserver free:1255 slab:2096 mapped:39 pagetables:585 bounce:0
Mar 20 20:29:55 nameserver DMA free:2056kB min:88kB low:108kB high:132kB active:5396kB inactive:5360kB present:16256kB pages_scanned:18338 all_unreclaimable? yes
Mar 20 20:29:55 nameserver lowmem_reserve[]: 0 492 492
Mar 20 20:29:55 nameserver Normal free:2964kB min:2792kB low:3488kB high:4188kB active:168224kB inactive:313692kB present:503924kB pages_scanned:959648 all_unreclaimable? yes
Mar 20 20:29:55 nameserver lowmem_reserve[]: 0 0 0
Mar 20 20:29:55 nameserver DMA: 2*4kB 0*8kB 0*16kB 2*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2056kB
Mar 20 20:29:55 nameserver Normal: 61*4kB 4*8kB 4*16kB 0*32kB 5*64kB 4*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2964kB
Mar 20 20:29:55 nameserver Swap cache: add 137283, delete 137280, find 5711/6808, race 0+0
Mar 20 20:29:55 nameserver Free swap = 0kB
Mar 20 20:29:55 nameserver Total swap = 497912kB
Mar 20 20:29:55 nameserver Free swap:      0kB
Mar 20 20:29:55 nameserver 131068 pages of RAM
Mar 20 20:29:55 nameserver 0 pages of HIGHMEM
Mar 20 20:29:55 nameserver 1969 reserved pages
Mar 20 20:29:55 nameserver 6476 pages shared
Mar 20 20:29:55 nameserver 3 pages swap cached
Mar 20 20:29:55 nameserver 0 pages dirty
Mar 20 20:29:55 nameserver 0 pages writeback
Mar 20 20:29:55 nameserver 39 pages mapped
Mar 20 20:29:55 nameserver 2096 pages slab
Mar 20 20:29:55 nameserver 585 pages pagetables
Mar 20 20:29:55 nameserver sshd invoked oom-killer: gfp_mask=0xa01d2, order=0, oomkilladj=0
Mar 20 20:29:55 nameserver [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] =======================
Mar 20 20:29:55 nameserver Mem-info:
Mar 20 20:29:55 nameserver DMA per-cpu:
Mar 20 20:29:55 nameserver CPU  0: Hot: hi:  0, btch:  1 usd:  0  Cold: hi:  0, btch:  1 usd:  0
Mar 20 20:29:55 nameserver Normal per-cpu:
Mar 20 20:29:55 nameserver CPU  0: Hot: hi: 186, btch: 31 usd: 26  Cold: hi:  62, btch: 15 usd: 55
Mar 20 20:29:55 nameserver Active:57254 inactive:65573 dirty:0 writeback:0 unstable:0
Mar 20 20:29:55 nameserver free:1291 slab:2082 mapped:4 pagetables:581 bounce:0
Mar 20 20:29:55 nameserver DMA free:2056kB min:88kB low:108kB high:132kB active:5488kB inactive:5268kB present:16256kB pages_scanned:18466 all_unreclaimable? yes
Mar 20 20:29:55 nameserver lowmem_reserve[]: 0 492 492
Mar 20 20:29:55 nameserver Normal free:3108kB min:2792kB low:3488kB high:4188kB active:223528kB inactive:257024kB present:503924kB pages_scanned:800552 all_unreclaimable? yes
Mar 20 20:29:55 nameserver lowmem_reserve[]: 0 0 0
Mar 20 20:29:55 nameserver DMA: 2*4kB 0*8kB 0*16kB 2*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2056kB
Mar 20 20:29:55 nameserver Normal: 83*4kB 9*8kB 5*16kB 0*32kB 5*64kB 4*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 3108kB
Mar 20 20:29:55 nameserver Swap cache: add 137552, delete 137549, find 5712/6821, race 0+0
Mar 20 20:29:55 nameserver Free swap = 0kB
Mar 20 20:29:55 nameserver Total swap = 497912kB
Mar 20 20:29:55 nameserver Free swap:      0kB
Mar 20 20:29:55 nameserver 131068 pages of RAM
Mar 20 20:29:55 nameserver 0 pages of HIGHMEM
Mar 20 20:29:55 nameserver 1969 reserved pages
Mar 20 20:29:55 nameserver 5993 pages shared
Mar 20 20:29:55 nameserver 3 pages swap cached
Mar 20 20:29:55 nameserver 0 pages dirty
Mar 20 20:29:55 nameserver 0 pages writeback
Mar 20 20:29:55 nameserver 4 pages mapped
Mar 20 20:29:55 nameserver 2082 pages slab
Mar 20 20:29:55 nameserver 581 pages pagetables
Mar 20 20:29:55 nameserver Out of memory: kill process 11272 (apache2) score 255800 or a child
Mar 20 20:29:55 nameserver Killed process 11626 (apache2)


I hope this helps you, devs, on the development of this software which I really like... And, by the way, the new version seems nice... Some javascript problems I had are now gone... Unfortunatelly, it doesn't seem quite stable for me to use on production yet...

Good luck and thanks for your time.

[Seanie]

I just installed the stable release, been using rc2 for as long as I can remember. First time I tried it, clicked the 'Personal Settings..Folders' tab and server disk thrashed, one httpd process went to >90%, and used 3 minutes+ of CPU time on a recent Xeon. An imapd process clocked up a few seconds of CPU time at the same time. I got the "120 seconds" error, but the rest of your error looks like a machine dying from load.

My httpd error log has:
[Mon Mar 24 15:15:39 2008] [error] [client 192.168.1.5] PHP Notice: DB Error: unknown error Query: UPDATE cache SET  created=now(), data='a:15011:{s:5:\\"Trash\\";a:3:{s:6:\\"RECENT\\";i:0;s:6:\\"UNSEEN\\";i:0;s:3:\\"ALL\\";i:0;}s:4:\\"Junk\\";a:3:{s:3:\\"ALL\\";i:0;s:6:\\"UNSEEN\\";i:0;s:6:\\"RECENT\\";i:0;}s:6:\\"Drafts\\";a:3:{s:6:\\"RECENT\\";i:0;s:6:\\"UNSEEN\\";i:0;s:3:\\"ALL\\";i:6;}s:5:\\"INBOX\\";a:3:{s:3:\\"ALL\\";i:41;s:6:\\"RECENT\\";i:0;s:6:\\"UNSEEN\\";i:0;}s:4:\\"Sent\\";a:3:{s:6:\\"RECENT\\";i:0;s:6:\\"UNSEEN\\";i:0;s:3:\\"ALL\\";i:46;}s:11:\\"account.php\\";a:1:{s:3:\\"ALL\\";i:1;}s:16:\\"account_edit.php\\";a:1:{s:3:\\"ALL\\";i:1;} in /var/www/htdocs/rcmail/program/include/bugs.inc on line 95, referer: http://www.mydomain.com/rcmail/

After putting some debug statements in the code, I could see a recursive listing of my home directory on the server - it doubles as a development server, and the IMAP function (iil_C_ListMailboxes?) that retrieves folders was going through my (very full) home folder, looking at every folder in there.

Moving the junk out temporarily made the action complete very quickly, with no detectable (to the eye!) load.

I'll put some effort into tracking the error down to something that could be fixed / improved in the next couple of days. If I make progress, I'll post here.

Hope this helps!

[Seanie]

Hmmm, ok so IMAP returns the recursive list of directories from a home folder as a result of an "lmb LIST" command, sent by iil_C_ListMailboxes.
With 4885 files and folders in my home directory, most of the code is executed in a fraction of a second, but the foreach statement in rcube_subscription_form takes 19 seconds. The page that is returned to the browser is 2.8MB in size. Before this test, I deleted all but one of very many large source trees from my home directory on the mail server.

The filename parsing and page construction doesn't look as though it could be improved upon, much. At least, it does several text scanning operations on each filepath it's presented with. Perhaps one way to improve on it would be to skip much of the processing for sub-directories whose parents aren't in the subscribed list? I might give that a spin, and if it enables me to continue lazily leaving source trees in my home directory, I'll post it here.

[Seanie]

This code reduces my 19 second wait down to just over 1 second. With more source trees (>19,000 files and directories), with the added code takes over 4 seconds, the original code takes ... more than 120 seconds, according to the error log (PHP max exe time exceeded). This might help you if you're doing IT on a shoestring, and using your mail server for other stuff too. There seem to be other 'issues' with the folder handling, but this mod does at least avoid punishing your server. If the idea behind the mod is attractive, I reckon it might be worth changing the code so it fetches (by name, using IMAP) only the folders listed as subscribed. I hope this is helpful, and not more easily done by setting a flag somewhere...

In program/steps/settings/manage_folders.inc, around line 203, first and last lines are original, and there's an extra close-curly-bracket to add before the foreach's close-curly-bracket:

  $level = count($foldersplit) - 1; /* <-- original line, insert following lines
      $parent_subscribed = TRUE;
      if ($level > 0)
      {
         $parentlevel = 0;
         $parent = $foldersplit[$parentlevel];
         while ($parentlevel < $level)
         {
            if(!in_array($parent, $a_subscribed))
            {
               $parent_subscribed = FALSE;
               break;
            }
            $parentlevel++;
            $parent = $parent . $delimiter . $foldersplit[$parentlevel];
         }
      }
      if ($parent_subscribed)
      {
         $display_folder = str_repeat('    ', $level) . rcube_charset_convert($foldersplit[$level], 'UTF-7');

[LeeUmm]

This looks promising. I've noticed after a few days of running the stable version, my server load is a bit higher. I don't have many users using roundcube, most use a mail client with pop3, so I can't say for sure it is the case, even after looking through some logs, but it seems too much of a coincidence not to be related, as I haven't changed anything else.

Not being a programmer, I'm a bit stuck on your code. I can add in your code, but where do I add the closing curly bracket? I read your statement about the foreach loop, but am not sure which it is as I don't really see anything. I see the last bit of your mod leaves an if statement open, so could you tell me around which lines to close it?

I just want to confirm first.

Thanks.

[Seanie]

Sorry, posted that in a bit of a rush. If you found the starting line, well done - this morning when I look again, it's only near line 203. My version of the file had lots of debugging lines added to it. Between the added lines and the end of the function there's only one line that contains only a single close-curly-bracket. That line closes the foreach loop that's commented "// create list of available folders". The extra close-curly-bracket should be added next to that one. The section of code (about 30 lines below the end of the piece I previously posted) should look like this:

   else
    $out .= '';

   $out .= "\n";
  } /* <--- new close-curly-bracket */
  }

 $out .= "\n";
 $out .= "\n$form_end";

As long as there are two close-curly-brackets there, the code will run. Indent to taste!
I've just noticed in my previous post that I've left a /* comment unclosed at the first line. I added that comment in the post - it's not in my code.

[LeeUmm]

Good stuff!

Just applied the changes so I'll monitor it over the next few days.

Much appreciated, cheers!

[LeeUmm]

Just wanted to come back and update that this is working great. The load has gone down a decent amount since using the patch. I've been monitoring the server with top/netstat etc and have seen the avg down, and this is on a VPS box with only a few clients. I can only imagine what the damage is on larger servers.

You should submit this patch to the trac and see what they say. I think it should be included asap.

Thanks again!

[Seanie]

Interesting that you notice a difference - the change should really only affect servers where users have interactive logons. Specifically, where users have large numbers of files in their home directories, and only where those files are stored in nested folders. For a plain old mail server where users just have a few files (or folders) in their home directories, and most folders are subscribed, the change may actually increase load.

[Akerbos]

I cannot tell of server crashes or the like, but I feel Roundcube got significantly slower since my update to 0.1-stable. It seems to take multiple times as long as 0.1-rc2.

Please note that I am the one and only user of my installation.

So you don't think your patch would help me?

[Seanie]

Akerbos - that code is only executed in one situation: when a user clicks on the "Folders" tab of their Personal Settings page. Otherwise, it will have no effect on roundcube mail at all. Our mail server has very few users, but at least one of them (me) has a very large number of large source trees in their home directory. If your mail server is only used for mail, I doubt my code is of any use to you at all. For it to be of use, a mail user would have to create a very large number of nested folders, and then unsubscribe them.

If you have deeply nested folders in your home directory on the server that you don't want to subscribe to, this code will speed up the display (reduce server load) of the Folders tab. If you don't, this code will slow it down (increase server load) a little.

I hope this helps!

[Akerbos]

I suppose it does - I know it won't help me. But I still don't know why the new version is that slow.

The new preview pane is a nice idea, but with this loading speed it's not usable.

[brewnchew]

I don't know if this will help in your situation but I also had a performance issue. It would take for ever going from one screen to the next. For example from the email to personal settings. I have been following the Upgrade instructions since RC1. The upgrade instructions did not cover changing your main.inc.php in your config folder.

I found when adding a new user that the standard folders (drafts, sent, junk, trash) did not auto create. After looking in the forum I found out about having a new variable set to true in main.inc.php. When I did a search I did not have that variable at all, remember I was basically using the RC1 main.inc.php file. I then compared the latest file from stable 0.1 and found a few new variables. I updated the main.inc.php file from stable 0.1 with my information and replaced my existing main.inc.php file. As soon as I logged in I noticed a huge difference. The pages just popped up from one to the other. It was back to working like it used to.

If the same holds true for you make sure to change the following from false to true. This is what actually started me looking and one of the variables that does not exist in the RC1 version of main.inc.php

Code: [Select]

// automatically create the above listed default folders on login
$rcmail_config['create_default_folders'] = TRUE;
I went from trying to fix my folders to fixing my performance.

Enjoy,

Chew

[Akerbos]

Thanks for the hint. I'm going to try this out soon and post feedback then.

[Akerbos]

I did what you suggested - no effect.

Changing folders takes forever, the "Not read" count in the menu lets me wait and on top of that, once deleted messages come back. I consider downgrading.

Edit: It's definitely RC - two other web based clients, running on the same machine, work as fast as ever.