slow performance for selecting reviewer

Are you responsible for making OJS work -- installing, upgrading, migrating or troubleshooting? Do you think you've found a bug? Post in this forum.

Moderators: jmacgreg, btbell, michael, bdgregg, barbarah, asmecher

Forum rules
The Public Knowledge Project Support Forum is moving to http://forum.pkp.sfu.ca

This forum will be maintained permanently as an archived historical resource, but all new questions should be added to the new forum. Questions will no longer be monitored on this old forum after March 30, 2015.
dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

slow performance for selecting reviewer

Postby dlove » Thu Jan 02, 2014 10:52 am

Hi, we currently have a journal that is having performance issues when selecting a reviewer (I'm not sure if there's other performance issues when doing other tasks at this point). When a reviewer is selected it takes a very long time to complete. I noticed that there was a previously reported issue for version 2.3.4 (pkp.sfu.ca/support/forum/viewtopic.php?f=8&t=7155) but we're running version 2.4.2 on Ubuntu 8.04.

The error log shows some errors but I'm not sure if it's related:

ojs2 has produced an error\n Message: WARNING: assert() [<a href='function.assert'>function.assert</a>]: Assertion failed\n In file: /var/www/cjc/lib/pkp/classes/db/DAO.inc.php\n At line: 499\n Stacktrace: \n Server info:\n OS: Linux\n PHP Version: 5.2.4-2ubuntu5.18\n Apache Version: Apache/2.2.8 (Ubuntu) PHP/5.2.4-2ubuntu5.18 with Suhosin-Patch\n DB Driver: mysql\n DB server version: 5.0.51a-3ubuntu5.7

ojs2 has produced an error\n Message: WARNING: assert() [<a href='function.assert'>function.assert</a>]: Assertion failed\n In file: /var/www/cjc/lib/pkp/classes/db/DAO.inc.php\n At line: 499\n Stacktrace: \n Server info:\n OS: Linux\n PHP Version: 5.2.4-2ubuntu5.18\n Apache Version: Apache/2.2.8 (Ubuntu) PHP/5.2.4-2ubuntu5.18 with Suhosin-Patch\n DB Driver: mysql\n DB server version: 5.0.51a-3ubuntu5.7

ojs2 has produced an error\n Message: WARNING: array_keys() [<a href='function.array-keys'>function.array-keys</a>]: The first argument should be an array\n In file: /var/www/cjc/lib/pkp/classes/core/DataObject.inc.php\n At line: 64\n Stacktrace: \n Server info:\n OS: Linux\n PHP Version: 5.2.4-2ubuntu5.18\n Apache Version: Apache/2.2.8 (Ubuntu) PHP/5.2.4-2ubuntu5.18 with Suhosin-Patch\n DB Driver: mysql\n DB server version: 5.0.51a-3ubuntu5.7

ojs2 has produced an error\n Message: WARNING: array_shift() [<a href='function.array-shift'>function.array-shift</a>]: The argument should be an array\n In file: /var/www/cjc/lib/pkp/classes/core/DataObject.inc.php\n At line: 65\n Stacktrace: \n Server info:\n OS: Linux\n PHP Version: 5.2.4-2ubuntu5.18\n Apache Version: Apache/2.2.8 (Ubuntu) PHP/5.2.4-2ubuntu5.18 with Suhosin-Patch\n DB Driver: mysql\n DB server version: 5.0.51a-3ubuntu5.7

There are also some jqueryUi 'File does not exist' errors, for example:

File does not exist: /var/www/cjc/lib/pkp/styles/lib/jqueryUi/images, referer: http://cjc-rcc.ucalgary.ca/cjc/index.php/rcc/search
File does not exist: /var/www/cjc/lib/pkp/styles/lib/jqueryUi/images, referer: http://cjc-rcc.ucalgary.ca/cjc/index.ph ... rch/search
File does not exist: /var/www/cjc/lib/pkp/styles/lib/jqueryUi/images, referer: http://cjc-rcc.ucalgary.ca/cjc/index.ph ... ew/222/499
File does not exist: /var/www/cjc/lib/pkp/styles/lib/jqueryUi/images, referer: http://cjc-rcc.ucalgary.ca/cjc/index.ph ... ew/222/499

Any help would be appreciated, thanks.

Darren

asmecher
Posts: 10015
Joined: Wed Aug 10, 2005 12:56 pm
Contact:

Re: slow performance for selecting reviewer

Postby asmecher » Thu Jan 02, 2014 11:06 am

Hi Darren,

Which part of the process is slow -- generating a list of reviewers, or choosing one to assign after the list has already been displayed?

Regards,
Alec Smecher
Public Knowledge Project Team

dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

Re: slow performance for selecting reviewer

Postby dlove » Thu Jan 02, 2014 11:14 am

Hi Alec, choosing a reviewer to assign after the list has already been displayed is slow. The list displays fine as far as I can tell.

Darren

asmecher
Posts: 10015
Joined: Wed Aug 10, 2005 12:56 pm
Contact:

Re: slow performance for selecting reviewer

Postby asmecher » Thu Jan 02, 2014 11:21 am

Hi Darren,

Hmm, that should be a fairly trivial operation. If you have access to your MySQL server's particulars, try turning on the slow query log to see which query is taking the time (assuming it is a MySQL issue, which is the most likely situation).

Are you using any plugins that might be performing extra tasks upon reviewer assignment?

Regards,
Alec Smecher
Public Knowledge Project Team

dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

Re: slow performance for selecting reviewer

Postby dlove » Thu Jan 02, 2014 11:28 am

Hi Alec, I'll look into MySQL further. I'll also have a look re: the plugins. I'll get back to you when I know more, thanks.

Darren

dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

Re: slow performance for selecting reviewer

Postby dlove » Thu Jan 02, 2014 12:17 pm

Hi Alec, I turned on the slow query log then selected a title in 'submissions in review', here's what I got:

# Time: 140102 12:15:32
# User@Host: localhost []
# Query_time: 16 Lock_time: 0 Rows_sent: 1 Rows_examined: 1318646
use ojs2;
SELECT rf.*
FROM review_forms rf
LEFT JOIN review_assignments rac ON (
rac.review_form_id = rf.review_form_id AND
rac.date_confirmed IS NOT NULL
)
LEFT JOIN review_assignments rai ON (
rai.review_form_id = rf.review_form_id AND
rai.date_notified IS NOT NULL AND
rai.date_confirmed IS NULL
)
WHERE rf.assoc_type = 256 AND rf.assoc_id = 1 AND rf.is_active = 1
GROUP BY rf.assoc_type, rf.assoc_id, rf.review_form_id, rf.seq, rf.is_active
HAVING COUNT(rac.review_id) > 0 OR COUNT(rai.review_id) > 0
ORDER BY rf.seq;

I don't want to assign a reviewer since this is an active journal so I will have to wait until one of the journal users does this before I can see the query results.

Darren

asmecher
Posts: 10015
Joined: Wed Aug 10, 2005 12:56 pm
Contact:

Re: slow performance for selecting reviewer

Postby asmecher » Thu Jan 02, 2014 1:49 pm

Hi Darren,

I wonder if you're missing an index... Try the following two queries and post the results:

Code: Select all

SHOW INDEXES FROM review_assignments;
SHOW INDEXES FROM review_forms;
Regards,
Alec Smecher
Public Knowledge Project Team

dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

Re: slow performance for selecting reviewer

Postby dlove » Thu Jan 02, 2014 2:27 pm

Hi Alec, here's the results:

Query: SHOW INDEXES FROM review_assignments;

Results:

Table Non_unique Key_name Seq_in_index Column_name Collation Cardinality Sub_part Packed Null Index_type Comment
review_assignments 0 PRIMARY 1 review_id A 1438 NULL NULL BTREE
review_assignments 1 review_assignments_submission_id 1 submission_id A 179 NULL NULL BTREE
review_assignments 1 review_assignments_reviewer_id 1 reviewer_id A 287 NULL NULL BTREE
review_assignments 1 review_assignments_form_id 1 review_form_id A 143 NULL NULL YES BTREE

Query: SHOW INDEXES FROM review_forms;

Results:

Table Non_unique Key_name Seq_in_index Column_name Collation Cardinality Sub_part Packed Null Index_type Comment
review_forms 0 PRIMARY 1 review_form_id A 1 NULL NULL BTREE


Darren

asmecher
Posts: 10015
Joined: Wed Aug 10, 2005 12:56 pm
Contact:

Re: slow performance for selecting reviewer

Postby asmecher » Fri Jan 03, 2014 6:32 am

Hi Darren,

Those indexes look as they should; we'll have to wait for a reviewer assignment to pop something new into the slow query log. Let me know when it does.

For the above query that was listed in the slow query log, try the patch linked here:
http://pkp.sfu.ca/bugzilla/show_bug.cgi?id=8527

The query in question was actually never used, so the patch will remove it.

Regards,
Alec Smecher
Public Knowledge Project Team

dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

Re: slow performance for selecting reviewer

Postby dlove » Fri Jan 03, 2014 8:08 am

Hi Alec, here are some more log file queries plus we asked the journal manager to send us a description of what he was doing when the delays were occurring:

Journal Manager:
"At 4:05 pm, I attempted to go into 2518 from the editor role. It took at least 10 seconds for it to open up the 2518 review screen. In the past, this access would have been immediate. Then I assigned myself as a reviewer for this article at about 4:07 pm, and after I pushed the button to assign myself, it took 18 seconds to bring me back to the review screen. Again, this used to take a second."

Logs:

# Time: 140102 16:05:53
# User@Host: localhost []
# Query_time: 16 Lock_time: 0 Rows_sent: 1 Rows_examined: 1318646
SELECT rf.*
FROM review_forms rf
LEFT JOIN review_assignments rac ON (
rac.review_form_id = rf.review_form_id AND
rac.date_confirmed IS NOT NULL
)
LEFT JOIN review_assignments rai ON (
rai.review_form_id = rf.review_form_id AND
rai.date_notified IS NOT NULL AND
rai.date_confirmed IS NULL
)
WHERE rf.assoc_type = 256 AND rf.assoc_id = 1 AND rf.is_active = 1
GROUP BY rf.assoc_type, rf.assoc_id, rf.review_form_id, rf.seq, rf.is_active
HAVING COUNT(rac.review_id) > 0 OR COUNT(rai.review_id) > 0
ORDER BY rf.seq;
# Time: 140102 16:08:11
# User@Host: localhost []
# Query_time: 16 Lock_time: 0 Rows_sent: 1 Rows_examined: 1319563
SELECT rf.*
FROM review_forms rf
LEFT JOIN review_assignments rac ON (
rac.review_form_id = rf.review_form_id AND
rac.date_confirmed IS NOT NULL
)
LEFT JOIN review_assignments rai ON (
rai.review_form_id = rf.review_form_id AND
rai.date_notified IS NOT NULL AND
rai.date_confirmed IS NULL
)
WHERE rf.assoc_type = 256 AND rf.assoc_id = 1 AND rf.is_active = 1
GROUP BY rf.assoc_type, rf.assoc_id, rf.review_form_id, rf.seq, rf.is_active
HAVING COUNT(rac.review_id) > 0 OR COUNT(rai.review_id) > 0
ORDER BY rf.seq;
# Time: 140103 1:00:06
# User@Host: localhost []
# Query_time: 3 Lock_time: 0 Rows_sent: 2098851 Rows_examined: 2098851
SELECT /*!40001 SQL_NO_CACHE */ * FROM `article_search_object_keywords`;
# Time: 140103 1:00:10
# User@Host: localhost []
# Query_time: 3 Lock_time: 0 Rows_sent: 915556 Rows_examined: 915556
SELECT /*!40001 SQL_NO_CACHE */ * FROM `notifications`;
/usr/sbin/mysqld, Version: 5.0.51a-3ubuntu5.7-log ((Ubuntu)). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
# Time: 140103 1:00:05
# User@Host: localhost []
# Query_time: 3 Lock_time: 0 Rows_sent: 2098851 Rows_examined: 2098851
use ojs2;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `article_search_object_keywords`;
# Time: 140103 1:00:11
# User@Host: localhost []
# Query_time: 4 Lock_time: 0 Rows_sent: 915556 Rows_examined: 915556
SELECT /*!40001 SQL_NO_CACHE */ * FROM `notifications`;


Thanks,

Darren

asmecher
Posts: 10015
Joined: Wed Aug 10, 2005 12:56 pm
Contact:

Re: slow performance for selecting reviewer

Postby asmecher » Fri Jan 03, 2014 8:36 am

Hi Darren,

This will be much easier to debug locally; would it be possible for you to send me a copy of a database backup? Feel free to anonymize as you like before sending, as long as the cardinalities and foreign keys stay roughly the same.

Regards,
Alec Smecher
Public Knowledge Project Team

dlove
Posts: 11
Joined: Wed Oct 31, 2007 2:43 pm

Re: slow performance for selecting reviewer

Postby dlove » Fri Jan 03, 2014 8:52 am

Hi Alec, thanks. I'll send it to you this morning.

Darren

shubhash
Posts: 43
Joined: Tue Feb 28, 2006 10:13 am
Contact:

Re: slow performance for selecting reviewer

Postby shubhash » Thu Mar 13, 2014 3:50 pm

Was it resolved?

We are seeing the same slowdown issues when assigning reviewers. Here is the slow query log:

Code: Select all

# Query_time: 25  Lock_time: 0  Rows_sent: 1  Rows_examined: 3398803
SELECT   rf.*
         FROM   review_forms rf
            LEFT JOIN review_assignments rac ON (
               rac.review_form_id = rf.review_form_id AND
               rac.date_confirmed IS NOT NULL
            )
            LEFT JOIN review_assignments rai ON (
               rai.review_form_id = rf.review_form_id AND
               rai.date_notified IS NOT NULL AND
               rai.date_confirmed IS NULL
            )
         WHERE   rf.assoc_type = 256 AND rf.assoc_id = 4 AND rf.is_active = 1
         GROUP BY rf.assoc_type, rf.assoc_id, rf.review_form_id, rf.seq, rf.is_active
         HAVING COUNT(rac.review_id) > 0 OR COUNT(rai.review_id) > 0
         ORDER BY rf.seq;

OJS version: 2.4.2
Thanks for any help.

shubhash
Posts: 43
Joined: Tue Feb 28, 2006 10:13 am
Contact:

Re: slow performance for selecting reviewer

Postby shubhash » Wed Mar 19, 2014 8:31 am

oops! I had missed the patch provided by Alec. The slow query is now gone. Thanks.


Return to “OJS Technical Support”

Who is online

Users browsing this forum: No registered users and 1 guest