I have been seen extremely slow page loads, on the order of 20 seconds for a simple front page.
In order to figure out what was going on I enabled the Query Log by navigating to Configuration/Development:DevelSettings and checking "Display query log" and below checking "Display page timer" and "Display memory usage." Of course, "Save Configuration."
When I cleared the caches and loaded the front page of the site, appended to the bottom of the page was all sorts of useful timing information, including an overview of timing (intial load and four reloads shown - 26 seconds, 18, 22, 19, 18):
Executed 901 queries in 20894.36 ms. Queries exceeding 5 ms are highlighted. Page execution time was 26944.43 ms. XHProf output. Memory used at: devel_boot()=1.29 MB, devel_shutdown()=54.19 MB, PHP peak=62 MB.
Executed 619 queries in 16402.68 ms. Queries exceeding 5 ms are highlighted. Page execution time was 18007.98 ms. XHProf output. Memory used at: devel_boot()=1.31 MB, devel_shutdown()=42.82 MB, PHP peak=48.5 MB.
Executed 620 queries in 18891.69 ms. Queries exceeding 5 ms are highlighted. Page execution time was 22824.29 ms. XHProf output. Memory used at: devel_boot()=1.13 MB, devel_shutdown()=42.79 MB, PHP peak=48.25 MB.
Executed 617 queries in 16338.84 ms. Queries exceeding 5 ms are highlighted. Page execution time was 19094.14 ms. XHProf output. Memory used at: devel_boot()=1.13 MB, devel_shutdown()=42.73 MB, PHP peak=48.25 MB.
Executed 614 queries in 16583.14 ms. Queries exceeding 5 ms are highlighted. Page execution time was 18206.06 ms. XHProf output. Memory used at: devel_boot()=1.13 MB, devel_shutdown()=42.71 MB, PHP peak=48.25 MB.
Scrolling through the details I found a bunch (over 200) instances of watchdog database logging calls like this:
40.81
364
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)
Using this as a clue, I searched Github/openscholar/openscholar for "dblog" and found os_update_7002() which enabled a module:
module_enable(array('dblog'));
Returning to OpenScholar I went to Admin/modules and found a module called "Database logging" near the top (11'th from the top). It was enabled. I disabled it and scrolled to the bottom and saved the configuration.
Now I cleared the caches and reloaded the front page. The timing is much improved (initial load and four reloads shown - 12 seconds, 3.6, 3.6, 1.5, 1.3):
Executed 490 queries in 4305.35 ms. Queries exceeding 5 ms are highlighted. Page execution time was 11830.13 ms. XHProf output. Memory used at: devel_boot()=1.29 MB, devel_shutdown()=50.44 MB, PHP peak=58.25 MB.
Executed 253 queries in 827.88 ms. Queries exceeding 5 ms are highlighted. Page execution time was 3603.57 ms. XHProf output. Memory used at: devel_boot()=1.31 MB, devel_shutdown()=39.93 MB, PHP peak=45.75 MB.
Executed 256 queries in 1342.39 ms. Queries exceeding 5 ms are highlighted. Page execution time was 3643.72 ms. XHProf output. Memory used at: devel_boot()=1.13 MB, devel_shutdown()=39.91 MB, PHP peak=45.75 MB.
Executed 250 queries in 440.99 ms. Queries exceeding 5 ms are highlighted. Page execution time was 1457.89 ms. XHProf output. Memory used at: devel_boot()=1.13 MB, devel_shutdown()=39.84 MB, PHP peak=45.75 MB.
Executed 250 queries in 346.25 ms. Queries exceeding 5 ms are highlighted. Page execution time was 1299.38 ms. XHProf output. Memory used at: devel_boot()=1.13 MB, devel_shutdown()=39.84 MB, PHP peak=45.75 MB.
Much better.
Note this is not a root cause fix as I don't know why so much database logging is going on or why it takes so much time.