1.4.2 = very slow <-> 1.3 = very fast?

[Frogman]

Hello all,

I've been running the coppermine 1.3.5 scripts now for a while for a much-viewed gallery, containing 2400 pictures a.t.m., nicely devided into categories and albums and folders and the gallery is growing every week.

I made the upgrade to 1.4.2 since I needed its album-password function.

The upgrade worked out, and the gallery is running 1.4.2 now, but why is it so damn slow where 1.3.5 went very fast.

I have the webserver that is running the gallery here in my home network and I see in my monitors that, everytime you request an image in an album, the cpu usage peaks to 100% for about 1.5 second, then he shows the page and transfers the image from server to client.
In 1.3.5 this went "click click click" and the pictures kept on coming.

My server is running latest stables of php4, mysql4.1 and apache2, his cpu is a 650mhz amd athlon

I just ask this because I don't see any big improvements that would require the 1.5 second php parse time. There are much bigger scripts to find, but they don't parse that long.

I'm posting this because you really should see what causes this high cpu usage(to me it seems like a bug), normally coppermine went very fast but now it isn't fun anymore to watch an album, it lags just too hard.
Even when I tried to turn off every option in the config which I didn't use (logging, ...).

Thanks in advance

Frogman.

[Tranz]

Any mods/hacks?

[Frogman]

Any mods/hacks?

No, no mods, no hacks, no addons, nothing that was not in the coppermine tarball.

And al the other php-mysql scripts on my server are running at their normal speeds, So it is coppermine itself that causes the lag.

Just to be certain: I love coppermine, but I report the slowness here because with all those new fast servers in the world the dev's might not see this lag problem

[Nibbler]

Enable debug mode in config. See how many db queries are being run and how long they take. Compare the page generation time with the total database query time.

[Frogman]

Here is the debug info for requesting 1 image:

USER:
------------------
Array
(
    [ID] => ccaa8f5e96e1ae992a04f5bd67c62d30
    [am] => 1
    [liv] => Array
        (
           

• => 450
              [1] => 358
              [2] => 1845
              [3] => 1844
              [4] => 1720
          )
  
      [uid] => 1
      [lang] => dutch
      [sort] => dd
      [lap] => 2
  )
  
  ==========================
  USER DATA:
  ------------------
  Array
  (
      [user_id] => 1
      [user_name] => Frogman
      [groups] => Array
          (
             
• => 1
          )
  
      [disk_max] => 0
      [disk_min] => 0
      [can_rate_pictures] => 1
      [can_send_ecards] => 1
      [ufc_max] => 3
      [ufc_min] => 3
      [custom_user_upload] => 0
      [num_file_upload] => 10
      [num_URI_upload] => 3
      [can_post_comments] => 1
      [can_upload_pictures] => 1
      [can_create_albums] => 1
      [has_admin_access] => 1
      [pub_upl_need_approval] => 0
      [priv_upl_need_approval] => 0
      [group_name] => Administrators
      [upload_form_config] => 3
      [group_quota] => 0
      [can_see_all_albums] => 1
      [group_id] => 1
  )
  
  ==========================
  Queries:
  ------------------
  Array
  (
     
• => SELECT extension, mime, content, player FROM scouts_filetypes; (0.001s)
      [1] => select * from scouts_plugins order by priority asc; (0.001s)
      [2] => delete from `scouts_fotos`.scouts_sessions where time<1134142065 and remember=0; (0.001s)
      [3] => delete from `scouts_fotos`.scouts_sessions where time<1132936065; (0.001s)
      [4] => select user_id from `scouts_fotos`.scouts_sessions where session_id=md5("9a08c5a59b89b1b6b080dde515ff4d8bf5a533a79d0175f16119dfbb5c9543a6"); (0.001s)
      [5] => select user_id as id, user_password as password from `scouts_fotos`.scouts_users where user_id=1 (0.001s)
      [6] => SELECT u.user_id AS id, u.user_name AS username, u.user_password AS password, u.user_group+100 AS group_id FROM `scouts_fotos`.scouts_users AS u INNER JOIN `scouts_fotos`.scouts_usergroups AS g ON u.user_group=g.group_id WHERE u.user_id='1' (0.001s)
      [7] => SELECT user_group_list FROM `scouts_fotos`.scouts_users AS u WHERE user_id='1' and user_group_list <> ''; (0.001s)
      [8] => SELECT MAX(group_quota) as disk_max, MIN(group_quota) as disk_min, MAX(can_rate_pictures) as can_rate_pictures, MAX(can_send_ecards) as can_send_ecards, MAX(upload_form_config) as ufc_max, MIN(upload_form_config) as ufc_min, MAX(custom_user_upload) as custom_user_upload, MAX(num_file_upload) as num_file_upload, MAX(num_URI_upload) as num_URI_upload, MAX(can_post_comments) as can_post_comments, MAX(can_upload_pictures) as can_upload_pictures, MAX(can_create_albums) as can_create_albums, MAX(has_admin_access) as has_admin_access, MIN(pub_upl_need_approval) as pub_upl_need_approval, MIN( priv_upl_need_approval) as  priv_upl_need_approval FROM scouts_usergroups WHERE group_id in (1) (0.001s)
      [9] => SELECT group_name FROM  scouts_usergroups WHERE group_id= 1 (0.001s)
      [10] => update `scouts_fotos`.scouts_sessions set time='1134145665' where session_id=md5('9a08c5a59b89b1b6b080dde515ff4d8bf5a533a79d0175f16119dfbb5c9543a6'); (0.001s)
      [11] => SELECT user_favpics FROM scouts_favpics WHERE user_id = 1 (0.002s)
      [12] => DELETE FROM scouts_banned WHERE expiry < '2005-12-09 17:27:46' (0.001s)
      [13] => SELECT * FROM scouts_banned WHERE (ip_addr='10.0.0.172' OR ip_addr='10.0.0.172' OR user_id=1) AND brute_force=0 (0.001s)
      [14] => SELECT COUNT(*) from scouts_pictures WHERE approved = 'YES'  (0.006s)
      [15] => SELECT * FROM scouts_pictures WHERE approved = 'YES'  ORDER BY pid DESC  LIMIT 1 ,1 (0.001s)
      [16] => SELECT title, comments, votes, category, aid FROM scouts_albums WHERE aid='81' LIMIT 1 (0.001s)
      [17] => SELECT name, parent FROM scouts_categories WHERE cid = '12' (0.001s)
      [18] => SELECT cid, name, parent FROM scouts_categories WHERE cid = '7' (0.001s)
      [19] => SELECT msg_id, msg_author, msg_body, UNIX_TIMESTAMP(msg_date) AS msg_date, author_id, author_md5_id, msg_raw_ip, msg_hdr_ip, pid FROM scouts_comments WHERE pid='3010' ORDER BY msg_id ASC (0.001s)
      [20] => SELECT COUNT(*) FROM scouts_pictures WHERE approved = 'NO' (0.005s)
      [21] => SELECT COUNT(*) from scouts_pictures WHERE approved = 'YES'  (0.006s)
      [22] => SELECT * FROM scouts_pictures WHERE approved = 'YES'  ORDER BY pid DESC  LIMIT 0 ,10 (0.002s)
  )
  
  ==========================
  GET :
  ------------------
  Array
  (
      [album] => lastup
      [cat] => 0
      [pos] => 1
  )
  
  ==========================
  POST :
  ------------------
  Array
  (
  )
  
  ==========================
  VERSION INFO :
  ------------------
  PHP version: 4.4.0-pl1-gentoo - OK
  ------------------
  mySQL version: 4.1.14-log
  ------------------
  Coppermine version: 1.4.2(stable)
  ==========================
  Module: GD
  ------------------
  GD Version: bundled (2.0.28 compatible)
  FreeType Support: 1
  FreeType Linkage: with freetype
  T1Lib Support: 1
  GIF Read Support: 1
  GIF Create Support: 1
  JPG Support: 1
  PNG Support: 1
  WBMP Support: 1
  XBM Support: 1
  JIS-mapped Japanese Font Support:
  
  ==========================
  Module: mysql
  ------------------
  MySQL Supportenabled
  Active Persistent Links 0
  Active Links 1
  Client API version 4.1.14
  MYSQL_MODULE_TYPE external
  MYSQL_SOCKET /var/run/mysqld/mysqld.sock
  MYSQL_INCLUDE -I/usr/include/mysql
  MYSQL_LIBS -L/usr/lib -lmysqlclient 
  ==========================
  Module: zlib
  ------------------
  ZLib Support enabled
  Compiled Version 1.2.3
  Linked Version 1.2.3
  ==========================
  Server restrictions (safe mode)?
  ------------------
  Directive | Local Value | Master Value
  safe_mode | Off | Off
  safe_mode_exec_dir | no value | no value
  safe_mode_gid | Off | Off
  safe_mode_include_dir | no value | no value
  safe_mode_exec_dir | no value | no value
  sql.safe_mode | Off | Off
  disable_functions | no value | no value
  file_uploads | On | On
  include_path | .:/usr/lib/php:/usr/lib/php/Smarty/ | .:/usr/lib/php:/usr/lib/php/Smarty/
  open_basedir | no value | no value
  ==========================
  email
  ------------------
  Directive | Local Value | Master Value
  sendmail_from | no value | no value
  sendmail_path | /usr/sbin/sendmail -t -i  | /usr/sbin/sendmail -t -i
  SMTP | localhost | localhost
  smtp_port | 25 | 25
  ==========================
  Size and Time
  ------------------
  Directive | Local Value | Master Value
  max_execution_time | 600 | 600
  max_input_time | 600 | 600
  upload_max_filesize | 10M | 10M
  post_max_size | 35M | 35M
  ==========================
  Page generated in 1.304 seconds - 23 queries in 0.039 seconds - Album set : ; Meta set: ;
  

Other warnings:

/include/functions.inc.php

    * Notice line 88: Undefined variable: cpg_show_private_album

/include/themes.inc.php

    * Notice line 2238: Undefined variable: report_tgt

/displayimage.php

    * Notice line 310: Undefined variable: meta_keywords

[Frogman]

additional info: the server was doing nothing else at that moment, he was completely idle, load 0.0

[Nibbler]

Well that rules out any issues with the database or with slow queries.

My server is running latest stables of php4, mysql4.1 and apache2, his cpu is a 650mhz amd athlon

No, you are not. Try updating. The only other thing I can suggest is to add timers into the code and try and track down what is causing the slowness.

[Frogman]

Well that rules out any issues with the database or with slow queries.

No, you are not. Try updating. The only other thing I can suggest is to add timers into the code and try and track down what is causing the slowness.

and how do I do this in the most simple way? (I know my way well enough into php, so a quick example should do it)

[Nibbler]

Add some code to your displayimage.php to give you elapsed time at that point, eg

after:

Code Select Expand


require('include/init.inc.php');


add

Code Select Expand


function echotime()
{
global $cpg_time_start;
echo cpgGetMicroTime() - $cpg_time_start . "<br />";
}


And then place the line

Code Select Expand


echotime();


At various places throughout the code and you'll get a time breakdown like this:

Code Select Expand


0.16439485549927
0.17091798782349
0.17272591590881
0.18417596817017


Then you can try to narrow down the section of code that takes so long.

[donnoman]

Something as got to be up with your setup.

I run my dev gallery on a celeron 500, with 6 plugins, and a content of the main page configured as:

Code Select Expand


minicms/breadcrumb/topn,1/toprated,1/catlist/alblist/random,1/lastup,1/lastalb,1/lastcom,1/lasthits,1/favpics,1


When Logged in as an admin I get:

Code Select Expand


Page generated in 0.996 seconds - 138 queries in 0.396 seconds - Album set : ; Meta set: ;


When logged in as a guest I get:

Code Select Expand


Page generated in 1.049 seconds - 145 queries in 0.438 seconds - Album set : ; Meta set: AND cpg140_pictures.aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


Actually, I just retested on the displayimage page instead of the index page as we should compare apples to apples, the displayimage page DOES take extra time:

Code Select Expand


Page generated in 1.476 seconds - 30 queries in 0.047 seconds - Album set : AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ; Meta set: AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


Here the ratio of total time vs sql time is about the same as what frogman is reporting. I thought maybe the call to get IPTC was taking a long time, but I have IPTC currently turned off.

Plugin system turned off:

Code Select Expand


Page generated in 0.274 seconds - 19 queries in 0.033 seconds - Album set : AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ; Meta set: AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


Plugin system ON, with no plugins activated:

Code Select Expand


Page generated in 0.272 seconds - 20 queries in 0.03 seconds - Album set : AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ; Meta set: AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


So one of my plugins certainly was taking extra time, (I have two plugins that have actions on the displayimage page, one watermarking, and one modifying the full size image, so the extra time isn't unexpected) I still haven't found the smoking gun.

Plugin ON, with no plugins activated, with IPTC and Exif  ON (subsequent loads of the page to make sure exif was using cached info):

Code Select Expand


Page generated in 0.287 seconds - 21 queries in 0.033 seconds - Album set : AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ; Meta set: AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


Still no smoking gun.

Plugin ON, with no plugins activated, with IPTC and Exif  ON with a LARGE image.

Code Select Expand


Page generated in 0.366 seconds - 21 queries in 0.042 seconds - Album set : AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ; Meta set: AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


Plugin ON, with no plugins activated, with IPTC and Exif  OFF with a LARGE image.

Code Select Expand


Page generated in 0.298 seconds - 20 queries in 0.034 seconds - Album set : AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ; Meta set: AND aid IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26) ;


This was a 350k image, so image size does have an impact when EXIF/IPTC are turned on. 

EXIF info is cached, IPTC is not. If you have IPTC turned on, but are not really using IPTC on your images, you will get a performance boost by turning it off particularly if you have a lot of big images in your gallery.

[Frogman]

Well, everything from the posts before point the cause of the lag to my server, but here I am to point the cause back to coppermine gallery.

I couldn't believe that I was running a bad configged php module for apache, so I installed a completely clean CPG1.4.2 on the same server and batch-added an album that is also in the big gallery which has been updated to from1.3.5 to 1.4.2.
And this gives us a clean conclusion:

Page generation time for watching the same picture from the same album in the big updated CPG1.4.2:
(the big album can be found here: http://www.needy.be/scouts_aarschot/thumbnails.php?album=11 )

Code Select Expand

Page generated in 1.263 seconds - 24 queries in 0.032 seconds - Album set : ; Meta set: ;

Page generation time for watching the same picture from the same album in a clean install CPG1.4.2:
(the clean install test album can be found here: http://www.needy.be/test/cpg142/thumbnails.php?album=1

Code Select Expand

Page generated in 0.313 seconds - 22 queries in 0.023 seconds - Album set : ; Meta set: ;

This rules out any issues with the server, it seems to me that either coppermine 1.4.2 can't handle big galleries(in contrary to 1.3.5, where it went fast) or that updated galleries lag and get very slow.

(I followed the readme pages to do a correct update)
EXIF & IPTC are OFF, plugin system is OFF on both albums

[Nibbler]

Language fallback may also be an issue. How do your settings compare there ?

[Frogman]

I think we've found the problem. And I guess there are 2 problems.

first problem(updated below):
I am unable to change the language in both installations, changing all other settings works.

language-lag problem:
So I tried with index.php?lang=english and index.php?lang=dutch
The big gallery goes fast in english and slow with the dutch lang-parameter
same for the test gallery.

Any idea how this could be fixed?

[Frogman]

update: when I closed my firefox and went back to the gallery the language settings became English, not perfectly, but it works.

[Joachim Müller]

Language fallback may also be an issue. How do your settings compare there ?

what are your settings for language fallback? If you only use english and dutch, turn language fallback off, as both languages come as "real" cpg1.4.x files that don't need fallback.

[Frogman]

Sorry, didn't read the fallback,

When fallback is off all languages go fast, when it is on they go slow, except english offcourse.

thanks for the work to find this out, it is maybe a good idea to put this somewhere in a FAQ, because it is something you don't think about right away.

[Huser]

My fallback setting is off but the gallery is still waaaaaayyyyyyyyyyy sloooooooowwwwww. Images keep reloading as well like sub menu images.

[Joachim Müller]

what's the use of your posting? Are you just ranting, or do you want actual help? If you want help, post a link to your page, and a non-admin test user account if needed.