0

On my localhost on Windows 7 sometimes a page load(after all cache clear/cron run) takes even 2 minutes. I've already enabled devel query log generated at the bottom of site showing query performance.

For a sample page total is 35 seconds, and following data is from this same page.

I've seperated queries taking more than 10ms in a separate file which totalled 25 seconds.

This is the first line of the query log:

Executed 5881 queries in 27114.36 ms. Queries exceeding 10 ms are highlighted. Page execution time was 34811.37 ms. Memory used at: devel_boot()=1.98 MB, devel_shutdown()=75.65 MB, PHP peak=77.25 MB.



From all the queries the highest time taking( 1471.69 ms) query is this one:

1471.69 1 DrupalDatabaseCache::getMultiple P A E SELECT cid, data, created, expire, serialized FROM cache_field WHERE cid IN (:cids_0, :cids_1, :cids_2, :cids_3, :cids_4, :cids_5, :cids_6, :cids_7, :cids_8, :cids_9, :cids_10, :cids_11, :cids_12, :cids_13, :cids_14, :cids_15, :cids_16, :cids_17, :cids_18, :cids_19, :cids_20, :cids_21, :cids_22, :cids_23, :cids_24, :cids_25, :cids_26, :cids_27, :cids_28, :cids_29, :cids_30, :cids_31, :cids_32, :cids_33, :cids_34, :cids_35, :cids_36, :cids_37, :cids_38, :cids_39, :cids_40, :cids_41, :cids_42, :cids_43, :cids_44, :cids_45, :cids_46, :cids_47, :cids_48, :cids_49, :cids_50, :cids_51, :cids_52, :cids_53, :cids_54, :cids_55, :cids_56, :cids_57, :cids_58, :cids_59, :cids_60, :cids_61, :cids_62, :cids_63, :cids_64, :cids_65, :cids_66, :cids_67, :cids_68, :cids_69, :cids_70, :cids_71, :cids_72, :cids_73, :cids_74, :cids_75, :cids_76, :cids_77, :cids_78, :cids_79, :cids_80, :cids_81, :cids_82, :cids_83, :cids_84, :cids_85, :cids_86, :cids_87, :cids_88, :cids_89, :cids_90, :cids_91, :cids_92, :cids_93, :cids_94, :cids_95, :cids_96, :cids_97, :cids_98, :cids_99, :cids_100, :cids_101, :cids_102, :cids_103, :cids_104, :cids_105, :cids_106, :cids_107, :cids_108, :cids_109, :cids_110, :cids_111, :cids_112, :cids_113, :cids_114, :cids_115, :cids_116, :cids_117, :cids_118, :cids_119, :cids_120, :cids_121, :cids_122, :cids_123, :cids_124, :cids_125, :cids_126, :cids_127, :cids_128, :cids_129, :cids_130, :cids_131, :cids_132, :cids_133, :cids_134, :cids_135, :cids_136, :cids_137, :cids_138, :cids_139, :cids_140, :cids_141, :cids_142, :cids_143, :cids_144, :cids_145, :cids_146, :cids_147, :cids_148, :cids_149, :cids_150, :cids_151, :cids_152, :cids_153, :cids_154, :cids_155, :cids_156, :cids_157, :cids_158, :cids_159, :cids_160, :cids_161, :cids_162, :cids_163, :cids_164, :cids_165, :cids_166, :cids_167, :cids_168, :cids_169, :cids_170, :cids_171, :cids_172, :cids_173, :cids_174, :cids_175, :cids_176, :cids_177, :cids_178, :cids_179, :cids_180, :cids_181, :cids_182, :cids_183, :cids_184, :cids_185, :cids_186, :cids_187, :cids_188, :cids_189, :cids_190, :cids_191, :cids_192, :cids_193, :cids_194, :cids_195, :cids_196, :cids_197, :cids_198, :cids_199, :cids_200, :cids_201, :cids_202, :cids_203, :cids_204, :cids_205, :cids_206, :cids_207, :cids_208, :cids_209, :cids_210, :cids_211, :cids_212, :cids_213, :cids_214, :cids_215, :cids_216, :cids_217, :cids_218, :cids_219, :cids_220, :cids_221, :cids_222, :cids_223, :cids_224, :cids_225, :cids_226, :cids_227, :cids_228, :cids_229, :cids_230, :cids_231, :cids_232, :cids_233, :cids_234, :cids_235, :cids_236, :cids_237, :cids_238)

The second list of time hogging queries are from watchdog table insert queries. The watchdog table I've is of 1.2 MB site with mysql tables installed as default(Innodb). I totalled one continuous series of (135) watchdog insert queries all taking more than 10 ms totalling 9000 ms( 25% of total time). Here is the sample query:

104.91 272 dblog_watchdog P A INSERT INTO watchdog (uid, type, message, variables, severity, link, location, referer, hostname, timestamp) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7, :db_insert_placeholder_8, :db_insert_placeholder_9)

So I'm looking for ways to reduce this watchdog insert time .. Couldn't find anything in Google. Any ideas?

2
  • 1
    You could just turn off the db log module if its causing that many problems. But really you should find out why it's inserting so many records on every page and stop it from happening. There are probably a bunch of php warnings getting logged or something, the dblog messages should help you find the exact lines of code and you can debug from there
    – Clive
    Commented Aug 14, 2013 at 9:40
  • It is due to silly messages like : Notice: Array to string conversion in DrupalDefaultEntityController->cacheGet() (line 369 of ....\includes\entity.inc). I've put @ in two lines in two files rather than disabling the module. Thanks for your suggestion.
    – AgA
    Commented Aug 14, 2013 at 10:47

2 Answers 2

0

Even though database logging is huge overhead to have on any web server, the logging is still a very important part of development so instead of using dblog, try using syslog instead. It is cheaper in terms of performance overheads and you can use a third party tool like papertrail to slap a web based UI on it for easy searching and diagnosis.

0

Sorry I forgot to tell. This mysql optimization almost solved my problem. The rest with enabling Views caching, using mod_deflate in Apache and using APC etc.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.