Extra slow logon

The place to talk about things that are related to CMS Made simple, but don't fit anywhere else.
Post Reply
Andrew Prior
Forum Members
Forum Members
Posts: 247
Joined: Sun Oct 28, 2007 4:14 am

Extra slow logon

Post by Andrew Prior »

I have a site which takes up to a minute to log in. Once I have been editing for a while, if I log out, I can log back in in a few seconds or even almost instantly. It seems to bear no relationship to the speed of the front end of the site, or the speed of editing, which is all fine.

I have corrected a few errors I found in the logs, but can make no further headway; I am too ignorant to interpret debugging info.

Can anyone spot what is probably obvious in the logs I have included below, and point me in the right direction? I'd be most grateful. Andrew Prior

System Info

Code: Select all

Cms Version: [b]1.11.9[/b]
Installed Modules:
	CMSMailer: [b]5.2.2[/b]
	FileManager: [b]1.4.3[/b]
	MenuManager: [b]1.8.6[/b]
	ModuleManager: [b]1.5.5[/b]
	News: [b]2.14.1[/b]
	nuSOAP: [b]1.0.2[/b]
	Printing: [b]1.1.2[/b]
	Search: [b]1.7.11[/b]
	ThemeManager: [b]1.1.8[/b]
	TinyMCE: [b]2.9.12[/b]
	CGFeedback: [b]1.6.2[/b]
	CGSimpleSmarty: [b]1.7.1[/b]
	CGExtensions: [b]1.38.1[/b]
	CGFeedMaker: [b]1.0.17[/b]
	Showtime: [b]3.3[/b]
	Captcha: [b]0.4.6[/b]
	CMSPrinting: [b]1.0.5[/b]
	MicroTiny: [b]1.2.5[/b]
	Album: [b]1.10.3[/b]
	Archiver: [b]0.2.6[/b]
	CGJobMgr: [b]1.3.1[/b]
	NMS: [b]2.7.4[/b]
	ErrorLogger: [b]1.1[/b]


Config Information:
	php_memory_limit: [b][/b]
	process_whole_template: [b]1[/b]
	output_compression: [b]false[/b]
	max_upload_size: [b]32000000[/b]
	url_rewriting: [b]mod_rewrite[/b]
	page_extension: [b].html[/b]
	query_var: [b]page[/b]
	image_manipulation_prog: [b]GD[/b]
	auto_alias_content: [b]true[/b]
	locale: [b][/b]
	default_encoding: [b][/b]
	admin_encoding: [b]utf-8[/b]
	set_names: [b]false[/b]


Php Information:
	phpversion: [b]5.3.18[/b]
	md5_function: [b]On[/b] (True)
	gd_version: [b]2[/b]
	tempnam_function: [b]On[/b] (True)
	magic_quotes_runtime: [b]Off[/b] (False)
	E_STRICT: [b]0[/b]
	E_DEPRECATED: [b]8192[/b]
	memory_limit: [b]128M[/b]
	max_execution_time: [b]90[/b]
	output_buffering: [b]On[/b]
	safe_mode: [b]Off[/b] (False)
	file_uploads: [b]On[/b] (True)
	post_max_size: [b]8M[/b]
	upload_max_filesize: [b]32M[/b]
	session_save_path: [b]/tmp[/b] (1777)
	session_use_cookies: [b]On[/b] (True)
	xml_function: [b]On[/b] (True)
	xmlreader_class: [b]On[/b] (True)


Server Information:
	Server Api: [b]cgi-fcgi[/b]
	Server Db Type: [b]MySQL (mysql)[/b]
	Server Db Version: [b]5.1.72[/b]
	Server Db Grants: [b]Found a "GRANT ALL" statement that appears to be suitable[/b
Debug Information

Code: Select all

[b]Before the first logon:[/b]
Debug is on. Redirecting disabled... Please click this link to continue.
http://dummytext.org/dummytext/login.php
Debug: (8.2E-5) - (usage: 1639520) - (peak: 1766392)
done loading required files
Debug: (0.028755) - (usage: 1679984) - (peak: 1766392)
Loading /home/dummytext/public_html/lib/classes/class.cms_cookies.php = 31576 bytes for an approximate total of 31576
Debug: (0.02898) - (usage: 1681120) - (peak: 1766392)
loading adodb
Debug: (0.03009) - (usage: 1812752) - (peak: 1909088)
loading page functions
Debug: (0.031629) - (usage: 2018296) - (peak: 2201144)
loading content functions
Debug: (0.031895) - (usage: 2031632) - (peak: 2201144)
loading translation functions
Debug: (0.032193) - (usage: 2047600) - (peak: 2201144)
loading php4 entity decode functions
Debug: (0.033773) - (usage: 2375800) - (peak: 2734072)
done loading files
Debug: (0.033818) - (usage: 2376208) - (peak: 2734072)
Initialize Database
Debug: (0.041351) - (usage: 3311528) - (peak: 3327568)
(mysql): SET 
Error (1064): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1
Debug: (0.041436) - (usage: 3310760) - (peak: 3369656)
Done Initializing Database
Debug: (0.056555) - (usage: 3312296) - (peak: 3369784)
(mysql): SELECT version from cms_version LIMIT  1
Debug: (0.056729) - (usage: 3311752) - (peak: 3370152)
Initialize Smarty
Debug: (0.067485) - (usage: 4988672) - (peak: 5000776)
Loading /home/dummytext/public_html/lib/classes/class.Smarty_CMS.php = 1675984 bytes for an approximate total of 1707560
Debug: (0.068367) - (usage: 5087448) - (peak: 5100128)
Loading /home/dummytext/public_html/lib/classes/class.CMSModuleDbTemplateResource.php = 83088 bytes for an approximate total of 1790648
Debug: (0.068864) - (usage: 5138512) - (peak: 5181216)
Loading /home/dummytext/public_html/lib/classes/class.CMSPageTemplateResource.php = 49560 bytes for an approximate total of 1840208
Debug: (0.06944) - (usage: 5203728) - (peak: 5248976)
Loading /home/dummytext/public_html/lib/classes/class.usertagoperations.inc.php = 63896 bytes for an approximate total of 1904104
Debug: (0.069763) - (usage: 5204312) - (peak: 5258744)
(mysql): SELECT * FROM cms_userplugins ORDER BY userplugin_name
Debug: (0.070241) - (usage: 5268552) - (peak: 5299288)
Loading /home/dummytext/public_html/lib/classes/class.cms_siteprefs.php = 29720 bytes for an approximate total of 1933824
Debug: (0.070564) - (usage: 5268768) - (peak: 5322632)
(mysql): SELECT sitepref_name,sitepref_value FROM cms_siteprefs
Debug: (0.109567) - (usage: 5578864) - (peak: 5830176)
Loading /home/dummytext/public_html/lib/classes/class.CMSNullTemplateResource.php = 19072 bytes for an approximate total of 1952896
Debug: (0.109712) - (usage: 5577296) - (peak: 5845856)
Done Initialiing Smarty
Debug display of 'Loading Modules':(0.109867) - (usage: 5577760) - (peak: 5845968)
Debug: (0.113089) - (usage: 5931320) - (peak: 6230936)
Loading /home/dummytext/public_html/lib/classes/class.moduleoperations.inc.php = 352528 bytes for an approximate total of 2305424
Debug: (0.113452) - (usage: 5932680) - (peak: 6230936)
(mysql): SELECT * FROM cms_modules ORDER BY module_name
Debug: (0.114185) - (usage: 5975632) - (peak: 6230936)
loading module Album
Debug: (0.120272) - (usage: 6920384) - (peak: 7297024)
Loading /home/dummytext/public_html/lib/classes/class.CMSModule.php = 612968 bytes for an approximate total of 2918392
Debug: (0.121035) - (usage: 7064848) - (peak: 7313904)
Loading /home/dummytext/public_html/lib/classes/class.CmsLangOperations.php = 68272 bytes for an approximate total of 2986664
Debug: (0.121603) - (usage: 7159256) - (peak: 7324216)
Loading /home/dummytext/public_html/lib/classes/class.CmsNlsOperations.php = 93408 bytes for an approximate total of 3080072
Debug: (0.122424) - (usage: 7219568) - (peak: 7370120)
Loading /home/dummytext/public_html/lib/classes/class.CmsNls.php = 45712 bytes for an approximate total of 3125784
Debug: (0.417815) - (usage: 7695520) - (peak: 8363632)
Loading /home/dummytext/public_html/lib/classes/class.CmsRoute.php = 49104 bytes for an approximate total of 3174888
Debug: (0.418458) - (usage: 7797120) - (peak: 8363632)
Loading /home/dummytext/public_html/lib/classes/class.cms_route_manager.php = 100304 bytes for an approximate total of 3275192
Debug: (0.418892) - (usage: 7809552) - (peak: 8363632)
loading module Archiver
Debug: (0.422167) - (usage: 8315304) - (peak: 8479232)
loading module Captcha
Debug: (0.424406) - (usage: 8631144) - (peak: 8768544)
loading module CGExtensions
Debug: (0.429673) - (usage: 9365800) - (peak: 9391776)
(mysql): SET @CG_ZEROTIME = NOW() - INTERVAL 150 YEAR,@CG_FUTURETIME = NOW() + INTERVAL 5 YEAR
Debug: (0.430317) - (usage: 9392840) - (peak: 9432872)
loading module CGSimpleSmarty
Debug: (0.432772) - (usage: 9677008) - (peak: 9749976)
loading module CMSMailer
Debug: (0.494669) - (usage: 9969288) - (peak: 10038008)
loading module ErrorLogger
Debug: (0.495915) - (usage: 10106128) - (peak: 10149560)
loading module FileManager
Debug: (0.561327) - (usage: 10364760) - (peak: 10425792)
loading module MenuManager
Debug: (0.813452) - (usage: 10619104) - (peak: 10673472)
loading module nuSOAP
Debug: (0.814431) - (usage: 10725936) - (peak: 10771128)
loading module Printing
Debug: (0.817515) - (usage: 10907200) - (peak: 10952240)
loading module Showtime
Debug: (0.81853) - (usage: 11036072) - (peak: 11078688)
loading module TinyMCE
Debug display of 'End of Loading Modules':(0.820973) - (usage: 11441904) - (peak: 11543136)
Debug: (0.821457) - (usage: 11483368) - (peak: 11543136)
Loading /home/dummytext/public_html/lib/classes/class.CmsRegularTaskHandler.php = 40616 bytes for an approximate total of 3315808
Debug: (0.821572) - (usage: 11413432) - (peak: 11554192)
No session found.  Now check for cookies
Debug: (0.821614) - (usage: 11413704) - (peak: 11554192)
No cookies found.  Redirect to log

[b]And also before the first logon...[/b]
Debug is on. Redirecting disabled... Please click this link to continue.
http://dummytext.org/dummytext/index.php?_sx_=4c607c8f
Debug: (5.7E-5) - (usage: 1760232) - (peak: 1899832)
done loading required files
Debug: (0.000487) - (usage: 1770144) - (peak: 1899832)
loading adodb
Debug: (0.001542) - (usage: 1901744) - (peak: 1997920)
loading page functions
Debug: (0.00299) - (usage: 2107224) - (peak: 2289848)
loading content functions
Debug: (0.003232) - (usage: 2120288) - (peak: 2289848)
loading translation functions
Debug: (0.00349) - (usage: 2136512) - (peak: 2289848)
loading php4 entity decode functions
Debug: (0.004914) - (usage: 2464608) - (peak: 2823048)
done loading files
Debug: (0.004959) - (usage: 2465016) - (peak: 2823048)
Initialize Database
Debug: (0.014359) - (usage: 3400344) - (peak: 3416432)
(mysql): SET 
Error (1064): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1
Debug: (0.014446) - (usage: 3399640) - (peak: 3458448)
Done Initializing Database
Debug: (0.014486) - (usage: 3399896) - (peak: 3458448)
Initialize Smarty
Debug: (0.025151) - (usage: 5076840) - (peak: 5089424)
Loading /home/dummytext/public_html/lib/classes/class.Smarty_CMS.php = 1675840 bytes for an approximate total of 1675840
Debug: (0.026063) - (usage: 5175656) - (peak: 5188768)
Loading /home/dummytext/public_html/lib/classes/class.CMSModuleDbTemplateResource.php = 83128 bytes for an approximate total of 1758968
Debug: (0.026603) - (usage: 5226720) - (peak: 5269904)
Loading /home/dummytext/public_html/lib/classes/class.CMSPageTemplateResource.php = 49560 bytes for an approximate total of 1808528
Debug: (0.027195) - (usage: 5291912) - (peak: 5329912)
Loading /home/dummytext/public_html/lib/classes/class.usertagoperations.inc.php = 63872 bytes for an approximate total of 1872400
Debug: (0.027596) - (usage: 5292232) - (peak: 5347376)
(mysql): SELECT * FROM cms_userplugins ORDER BY userplugin_name
Debug: (0.028141) - (usage: 5356456) - (peak: 5387752)
Loading /home/dummytext/public_html/lib/classes/class.cms_siteprefs.php = 29696 bytes for an approximate total of 1902096
Debug: (0.028466) - (usage: 5356800) - (peak: 5411088)
(mysql): SELECT sitepref_name,sitepref_value FROM cms_siteprefs
Debug: (0.032004) - (usage: 5666944) - (peak: 5911432)
Loading /home/dummytext/public_html/lib/classes/class.CMSNullTemplateResource.php = 19096 bytes for an approximate total of 1921192
Debug: (0.032075) - (usage: 5665376) - (peak: 5933720)
Done Initialiing Smarty
Debug display of 'Loading Modules':(0.032161) - (usage: 5665840) - (peak: 5933832)
Debug: (0.034381) - (usage: 6019464) - (peak: 6319024)
Loading /home/dummytext/public_html/lib/classes/class.moduleoperations.inc.php = 352592 bytes for an approximate total of 2273784
Debug: (0.034615) - (usage: 6020824) - (peak: 6319024)
(mysql): SELECT * FROM cms_modules ORDER BY module_name
Debug: (0.035054) - (usage: 6063784) - (peak: 6319024)
loading module Album
Debug: (0.040895) - (usage: 7008504) - (peak: 7385632)
Loading /home/dummytext/public_html/lib/classes/class.CMSModule.php = 612904 bytes for an approximate total of 2886688
Debug: (0.04189) - (usage: 7152984) - (peak: 7402440)
Loading /home/dummytext/public_html/lib/classes/class.CmsLangOperations.php = 68272 bytes for an approximate total of 2954960
Debug: (0.042679) - (usage: 7247360) - (peak: 7412208)
Loading /home/dummytext/public_html/lib/classes/class.CmsNlsOperations.php = 93384 bytes for an approximate total of 3048344
Debug: (0.043509) - (usage: 7307656) - (peak: 7458088)
Loading /home/dummytext/public_html/lib/classes/class.CmsNls.php = 45720 bytes for an approximate total of 3094064
Debug: (0.056293) - (usage: 7783552) - (peak: 8451824)
Loading /home/dummytext/public_html/lib/classes/class.CmsRoute.php = 49104 bytes for an approximate total of 3143168
Debug: (0.057101) - (usage: 7885152) - (peak: 8451824)
Loading /home/dummytext/public_html/lib/classes/class.cms_route_manager.php = 100304 bytes for an approximate total of 3243472
Debug: (0.057576) - (usage: 7897584) - (peak: 8451824)
loading module Archiver
Debug: (0.059927) - (usage: 8403112) - (peak: 8567768)
loading module Captcha
Debug: (0.06184) - (usage: 8718960) - (peak: 8856896)
loading module CGExtensions
Debug: (0.06712) - (usage: 9453896) - (peak: 9479800)
(mysql): SET @CG_ZEROTIME = NOW() - INTERVAL 150 YEAR,@CG_FUTURETIME = NOW() + INTERVAL 5 YEAR
Debug: (0.067747) - (usage: 9480944) - (peak: 9520896)
loading module CGSimpleSmarty
Debug: (0.070164) - (usage: 9765152) - (peak: 9838104)
loading module CMSMailer
Debug: (0.071979) - (usage: 10057424) - (peak: 10126064)
loading module ErrorLogger
Debug: (0.073094) - (usage: 10194272) - (peak: 10237704)
loading module FileManager
Debug: (0.074881) - (usage: 10452888) - (peak: 10513968)
loading module MenuManager
Debug: (0.078873) - (usage: 10707232) - (peak: 10762640)
loading module nuSOAP
Debug: (0.079747) - (usage: 10814008) - (peak: 10859248)
loading module Printing
Debug: (0.082827) - (usage: 10995264) - (peak: 11040312)
loading module Showtime
Debug: (0.083853) - (usage: 11124136) - (peak: 11166752)
loading module TinyMCE
Debug display of 'End of Loading Modules':(0.086331) - (usage: 11529960) - (peak: 11630920)
Debug: (0.086822) - (usage: 11571416) - (peak: 11630920)
Loading /home/dummytext/public_html/lib/classes/class.CmsRegularTaskHandler.php = 40608 bytes for an approximate total of 3284080
Debug: (0.087184) - (usage: 11522416) - (peak: 11642096)
No session found.  Now check for cookies
Debug: (0.08723) - (usage: 11522688) - (peak: 11642096)
No cookies found.  Redirect to login.
Debug: (0.088018) - (usage: 11618632) - (peak: 11676720)
Loading /home/dummytext/public_html/lib/classes/class.useroperations.inc.php = 94688 bytes for an approximate total of 3378768
Debug: (0.12051) - (usage: 11623640) - (peak: 11686408)
(mysql): SELECT u.user_id FROM cms_users u LEFT JOIN cms_user_groups ug ON u.user_id = ug.user_id WHERE username = 'dummytext' AND password = '4da01b3b79cc3e9c626444ef4adf08e1' AND u.active = 1 AND admin_access = 1 LIMIT  1
Debug: (0.120978) - (usage: 11623984) - (peak: 11691056)
(mysql): SELECT username, password, active, first_name, last_name, admin_access, email FROM cms_users WHERE user_id = '1'
Debug: (0.121078) - (usage: 11621024) - (peak: 11693640)
Got user by username
Debug: (0.121117) - (usage: 11621200) - (peak: 11694416)
User Object
(
    [id] => 1
    [username] => dummytext
    [password] => not telling you this
    [firstname] => Admin
    [lastname] => User
    [email] => andrew@dummytext.com
    [active] => 1
    [adminaccess] => 1
)
Debug: (0.121156) - (usage: 11621840) - (peak: 11694416)
Starting login procedure.  Setting userid so that other pages will pick it up and set a cookie.
Debug: (0.121321) - (usage: 11625088) - (peak: 11694728)
(mysql): SELECT username, password, active, first_name, last_name, admin_access, email FROM cms_users WHERE user_id = '1'
Debug: (0.121833) - (usage: 11656736) - (peak: 11706248)
Loading /home/dummytext/public_html/lib/classes/class.cms_cookies.php = 31568 bytes for an approximate total of 3410336
Debug: (0.122439) - (usage: 11715128) - (peak: 11790856)
Loading /home/dummytext/public_html/lib/classes/class.cms_utils.php = 56928 bytes for an approximate total of 3467264
Debug: (0.122861) - (usage: 11718144) - (peak: 11790856)
(mysql): INSERT INTO cms_adminlog (timestamp, user_id, username, item_id, item_name, action, ip_addr) VALUES (1386284556,'1','dummytext','1','Admin Username: dummytext','Logged In','203.122.240.177')
Debug: (0.123802) - (usage: 11841328) - (peak: 11910792)
Loading /home/dummytext/public_html/lib/classes/class.Events.php = 127104 bytes for an approximate total of 3594368
Debug: (0.123996) - (usage: 11843176) - (peak: 11910792)
(mysql): SELECT eh.tag_name, eh.module_name, e.originator, e.event_name, eh.handler_order, eh.handler_id, eh.removable FROM cms_event_handlers eh
        INNER JOIN cms_events e ON e.event_id = eh.event_id
        ORDER BY eh.handler_order ASC
Debug: (0.124288) - (usage: 11879896) - (peak: 11910792)
(mysql): SELECT version from cms_version LIMIT  1
Debug: (0.124413) - (usage: 11880248) - (peak: 11943688)
Found login_user_id.  Going to generate the user object.
Debug: (0.124577) - (usage: 11883584) - (peak: 11945064)
(mysql): SELECT username, password, active, first_name, last_name, admin_access, email FROM cms_users WHERE user_id = '1'
Top
JohnnyB
Dev Team Member
Dev Team Member
Posts: 731
Joined: Tue Nov 21, 2006 5:05 pm

Re: Extra slow logon

Post by JohnnyB »

Has this been upgraded from an older CMSMS version?
Maybe there's an error or deprecated config values in the config.php file.


I can't see why it might be slow for the initial log in, but here's a couple things that I think should change:
phpversion: 5.3.18
E_DEPRECATED: 8192
PHP 5.3 should be running 5.3.28. Not because of CMSMMS, but because there was a security issue with older 5.3 releases.

Error reporting should have E_DEPRECATED off (for CMSMS)
You can do this in the server's php.ini file:
error_reporting = E_ALL & ~E_DEPRECATED
"The art of life lies in a constant readjustment to our surroundings." -Okakura Kakuzo

--
LinkedIn profile
--
I only speak/write in English so I may not translate well on International posts.
--
Top
Post Reply

Return to “The Lounge”