Admin: Journal-Settings: 'Sections' tab loads over 60 seconds!

Commifreak · June 21, 2019, 5:05am

I’ve created a PHP Slow-Log. I dont now if that points us into the right direction

[21-Jun-2019 07:04:37]  [pool test2.ojs.openagrar.de] pid 22614
script_filename = /var/www/test2.ojs.openagrar.de/index.php
[0x00007f769441f1e0] file_exists() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/i18n/LocaleFile.inc.php:143
[0x00007f769441f170] isValid() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/i18n/LocaleFile.inc.php:85
[0x00007f769441f080] translate() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/i18n/PKPLocale.inc.php:104
[0x00007f769441efa0] translate() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/i18n/PKPLocale.inc.php:751
[0x00007f769441ef10] __() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/linkAction/LinkAction.inc.php:104
[0x00007f769441ee90] getHoverTitle() /var/www/test2.ojs.openagrar.de/cache/t_compile/57b0af70e0aa3343878f8006f5041e2a81dc4977^%%59^592^592A5FEF%%linkActionButton.tpl.php:6
[0x00007f769441ee00] [INCLUDE_OR_EVAL]() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1870
[0x00007f769441ed30] _smarty_include() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/template/PKPTemplateManager.inc.php:416
[0x00007f769441ecb0] _smarty_include() /var/www/test2.ojs.openagrar.de/cache/t_compile/57b0af70e0aa3343878f8006f5041e2a81dc4977^%%9B^9B0^9B0BB3F9%%linkAction.tpl.php:14
[0x00007f769441ec00] [INCLUDE_OR_EVAL]() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1870
[0x00007f769441eb30] _smarty_include() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/template/PKPTemplateManager.inc.php:416
[0x00007f769441eab0] _smarty_include() /var/www/test2.ojs.openagrar.de/cache/t_compile/57b0af70e0aa3343878f8006f5041e2a81dc4977^%%DC^DC7^DC7D51C2%%gridRow.tpl.php:98
[0x00007f769441e9c0] [INCLUDE_OR_EVAL]() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1264
[0x00007f769441e7f0] fetch() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/template/PKPTemplateManager.inc.php:793
[0x00007f769441e730] fetch() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:1024
[0x00007f769441e660] renderRowInternally() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:990
[0x00007f769441e590] renderRowsInternally() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:1035
[0x00007f769441e4d0] renderGridBodyPartsInternally() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:927
[0x00007f769441e430] doSpecificFetchGridActions() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:642
[0x00007f769441e370] fetchGrid() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/core/PKPRouter.inc.php:372

Another one:

[21-Jun-2019 07:02:41]  [pool test2.ojs.openagrar.de] pid 22579
script_filename = /var/www/test2.ojs.openagrar.de/index.php
[0x00007f769441ef70] is_readable() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/internals/core.get_include_path.php:34
[0x00007f769441ee80] smarty_core_get_include_path() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1650
[0x00007f769441eda0] _parse_resource_name() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1544
[0x00007f769441ecb0] _fetch_resource_info() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1388
[0x00007f769441ec00] _is_compiled() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1867
[0x00007f769441eb30] _smarty_include() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/template/PKPTemplateManager.inc.php:416
[0x00007f769441eab0] _smarty_include() /var/www/test2.ojs.openagrar.de/cache/t_compile/57b0af70e0aa3343878f8006f5041e2a81dc4977^%%DC^DC7^DC7D51C2%%gridRow.tpl.php:98
[0x00007f769441e9c0] [INCLUDE_OR_EVAL]() /var/www/test2.ojs.openagrar.de/lib/pkp/lib/vendor/smarty/smarty/libs/Smarty.class.php:1264
[0x00007f769441e7f0] fetch() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/template/PKPTemplateManager.inc.php:793
[0x00007f769441e730] fetch() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:1024
[0x00007f769441e660] renderRowInternally() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:990
[0x00007f769441e590] renderRowsInternally() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:1035
[0x00007f769441e4d0] renderGridBodyPartsInternally() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:927
[0x00007f769441e430] doSpecificFetchGridActions() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/controllers/grid/GridHandler.inc.php:642
[0x00007f769441e370] fetchGrid() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/core/PKPRouter.inc.php:372
[0x00007f769441e290] _authorizeInitializeAndCallRequest() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/core/PKPComponentRouter.inc.php:256
[0x00007f769441e1f0] route() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/core/Dispatcher.inc.php:134
[0x00007f769441e110] dispatch() /var/www/test2.ojs.openagrar.de/lib/pkp/classes/core/PKPApplication.inc.php:243
[0x00007f769441e0a0] execute() /var/www/test2.ojs.openagrar.de/index.php:68

As mentioned by https://serverpilot.io/docs/how-to-read-the-php-slow-request-log the bottleneck here was is_readable and file_exists. I could increase the slowlog timeout, to get more accurate results.

asmecher · June 25, 2019, 7:39pm

Hi @Commifreak,

I haven’t used the PHP slow log before, but I suspect it’s a red herring here – the Sections tab operates by fetching a list of sections, executing several queries for each section, and building the results into markup. The slow query log will tell you what code was executing when it exceeded the timeout threshold, but in this case I don’t think it’s a single slow function call but an aggregate effect of the data being fetched and presented.

I think a likelier cause is the database, specifically a query that is neither very fast nor very slow but is being run so many times for your section list that the cumulative effect becomes a problem. (This is bolstered by the considerable performance improvement you saw when dropping the list size.)

Before we start debugging that, is your database server running on the same machine as your web server?

Regards,
Alec Smecher
Public Knowledge Project Team

Commifreak · June 26, 2019, 4:53am

Hi!

thanks for your detailed answer!

No, the DB Server is NOT running on the same machine. I have a dedicated MySQL Server instance.

asmecher · June 26, 2019, 2:56pm

Hi @Commifreak,

Building OJS pages currently requires a lot of database queries, and I’ve heard anecdotally that running on a separate DB server introduces enough overhead in each to degrade performance. (I haven’t worked with this myself.) I’d suggest trying a local MySQL install to see if that resolves the performance issue.

Regards,
Alec Smecher
Public Knowledge Project Team

diegomejia07 · November 12, 2021, 9:43pm

Hi @asmecher,

There is some patch or some modification, that can apply to the version of OJS 3.2.1.4, to solve this same problem, since the loading of the back issues is still very slow.

shantanusingh · June 22, 2022, 3:28pm

How to set page number in back issues.