Error 503 Backend fetch failed to grid/users/reviewer-select/reviewer-select-grid/fetch-grid

Glauco_Roberto_Munsb · May 13, 2017, 4:20pm

Hi! I have this problem at list the reviewers available

After 1,5 minutes elapsed the console show this error
Error 503 Backend fetch failed
on console can see this

the requires was index.php/rbagroecologia/$$$call$$$/grid/users/reviewer-select/reviewer-select-grid/fetch-grid?submissionId=22060&stageId=3&reviewRoundId=16553&_=1494688120108
Looking to php log a find the error, but I not sure it is the problem.PHP Warning: Cannot use a scalar value as an array in revistas/lib/pkp/classes/core/DataObject.inc.php on line 133
@asmecher you have some tip to me?

Glauco_Roberto_Munsb · May 13, 2017, 4:34pm

something similar by @alexxxmendonca at this topic Reviewer list won't load (OJS 3.0.2.0) - #5 by alexxxmendonca at the same line, but my issue not show any json_encode() or other info.

asmecher · May 14, 2017, 3:10am

Hi @Glauco_Roberto_Munsb,

In your PHP configuration, are error messages configured to go to the browser? If so, change your configuration so they’re sent to the log only.

Regards,
Alec Smecher
Public Knowledge Project Team

Glauco_Roberto_Munsb · May 17, 2017, 12:51am

Hi @asmecher display_errors is off on php.ini and config.inc.php so I set the show_stacktrace=Off in config.inc.php, but the erro still the same:

Error 503 Backend fetch failed
Backend fetch failed
Guru Meditation:
XID: 33256689
Varnish cache server

asmecher · May 17, 2017, 2:36pm

Hi @Glauco_Roberto_Munsb,

I think something outside of OJS is happening here – OJS never reports a 503 error. I would suggest exploring your server’s error logs (possibly beyond your PHP error logs).

Regards,
Alec Smecher
Public Knowledge Project Team

Glauco_Roberto_Munsb · May 19, 2017, 1:15pm

You are right @asmecher! The server cut the process after 90 seconds. You recommend some optimize process in tables (like new index) to down this time?

asmecher · May 19, 2017, 3:29pm

Hi @Glauco_Roberto_Munsb,

That’s not typically a query that should take a long time, but there are lots of variables that might be involved. If you’re able, I’d suggest configuring MySQL to enable a slow query log; that’ll allow you to capture and inspect the problem query, if it is indeed a database problem, and perhaps I can help identify the bottleneck from there.

Regards,
Alec Smecher
Public Knowledge Project Team

Glauco_Roberto_Munsb · May 21, 2017, 12:58pm

@asmecher you can point the exact file or the query generated to show the reviewer-select, with that, I can simulate and provide some solution, in case, I can return the solution because some others maybe have the same problem too.

Glauco_Roberto_Munsb · May 23, 2017, 1:02am

Hi @asmecher one more tip: After searching on database looking the indexes. I found this: when I filter in Users & Roles for reviewer userGroup = 16 the search was quick. Only in reviewer-select function we have this problem.

ctgraham · May 23, 2017, 12:49pm

I think this ultimately comes down to the PKPUserDAO::getFilteredReviews() function:

github.com

pkp/pkp-lib/blob/f5bfb45335199a5a32999257e2de321f870c31d4/classes/user/PKPUserDAO.inc.php#L243-L310


	function getFilteredReviewers($contextId, $stageId, $name = null, $doneMin = null, $doneMax = null, $avgMin = null, $avgMax = null, $lastMin = null, $lastMax = null, $activeMin = null, $activeMax = null, $interests = array(), $submissionId = null, $reviewRoundId = null, $reviewRound = null, $rangeInfo = null) {
		// Timestamp math appears not to work in seconds in MySQL. Issue #1167.
		switch (Config::getVar('database', 'driver')) {
			case 'mysql':
			case 'mysqli':
				$dateDiffClause = 'DATEDIFF(rac.date_completed, rac.date_notified)';
				break;
			default:
				$dateDiffClause = 'DATE_PART(\'day\', rac.date_completed - rac.date_notified)';
		}
		$result = $this->retrieveRange(
			'SELECT	u.*,
				COUNT(DISTINCT rac.review_id) AS complete_count,
				AVG(' . $dateDiffClause . ') AS average_time,
				MAX(raf.date_assigned) AS last_assigned,
				COUNT(DISTINCT rai.review_id) AS incomplete_count
			FROM	users u
				JOIN user_user_groups uug ON (uug.user_id = u.user_id)
				JOIN user_groups ug ON (ug.user_group_id = uug.user_group_id AND ug.role_id = ? AND ug.context_id = ?)
				JOIN user_group_stage ugs ON (ugs.user_group_id = ug.user_group_id AND ugs.stage_id = ?)

This file has been truncated. show original

There’s a lot of LEFT JOINing on review_assignments there. What is the current number of entries in the tables specified in this query (users, user_user_groups, user_groups, user_group_stage, review_assignments)?

Glauco_Roberto_Munsb · May 23, 2017, 11:12pm

Hi @ctgraham I have 10.446 rows after 1.3923 seconds executing the query on mysql. Ten thousand is a number big in this case?
SQL

SELECT u.*, COUNT(DISTINCT rac.review_id) AS complete_count, AVG(DATEDIFF(rac.date_completed, rac.date_notified)) AS average_time, MAX(raf.date_assigned) AS last_assigned, COUNT(DISTINCT rai.review_id) AS incomplete_count FROM users u JOIN user_user_groups uug ON (uug.user_id = u.user_id) JOIN user_groups ug ON (ug.user_group_id = uug.user_group_id AND ug.role_id is not null AND ug.context_id is not null) JOIN user_group_stage ugs ON (ugs.user_group_id = ug.user_group_id AND ugs.stage_id is not null) LEFT JOIN review_assignments ras ON (ras.submission_id is not null AND ras.stage_id is not null AND ras.review_round_id is not null AND ras.reviewer_id=u.user_id) LEFT JOIN review_assignments rac ON (rac.reviewer_id = u.user_id AND rac.date_notified IS NOT NULL AND rac.date_completed IS NOT NULL) LEFT JOIN review_assignments raf ON (raf.reviewer_id = u.user_id) LEFT JOIN review_assignments ran ON (ran.reviewer_id = u.user_id AND ran.review_id > raf.review_id) LEFT JOIN review_assignments rai ON (rai.reviewer_id = u.user_id AND rai.date_notified IS NOT NULL AND rai.date_completed IS NULL AND rai.cancelled = 0 AND rai.declined = 0 AND rai.replaced = 0) WHERE ras.review_id IS NULL AND ran.review_id IS NULL GROUP BY u.user_id HAVING 1=1 ORDER BY last_name, first_name

ctgraham · May 24, 2017, 12:24pm

By replacing the query parameters from user_user_groups and user_group_stage with “is not null”, you are definitely over-sampling. In the native code, these will always filter into a specific role, context, and stage.

How many entries do you have in each table individually?

Another potentially explosive set of joins I missed earlier is the IN clause for user_interests and controlled_vocab_entry_settings.

github.com

pkp/pkp-lib/blob/f5bfb45335199a5a32999257e2de321f870c31d4/classes/user/PKPUserDAO.inc.php#L271


				JOIN user_groups ug ON (ug.user_group_id = uug.user_group_id AND ug.role_id = ? AND ug.context_id = ?)
				JOIN user_group_stage ugs ON (ugs.user_group_id = ug.user_group_id AND ugs.stage_id = ?)
				LEFT JOIN review_assignments ras ON (ras.submission_id = ? AND ras.stage_id = ? AND ras.review_round_id = ? AND ras.reviewer_id=u.user_id)
				LEFT JOIN review_assignments rac ON (rac.reviewer_id = u.user_id AND rac.date_notified IS NOT NULL AND rac.date_completed IS NOT NULL)
				LEFT JOIN review_assignments raf ON (raf.reviewer_id = u.user_id)
				LEFT JOIN review_assignments ran ON (ran.reviewer_id = u.user_id AND ran.review_id > raf.review_id)
				LEFT JOIN review_assignments rai ON (rai.reviewer_id = u.user_id AND rai.date_notified IS NOT NULL AND rai.date_completed IS NULL AND rai.declined = 0 AND rai.replaced = 0)
			WHERE	ras.review_id IS NULL
				AND ran.review_id IS NULL' .
				($reviewRound !== null ? ' AND rac.submission_id = ? AND rac.stage_id = ? AND rac.round < ?':'') .
				str_repeat(' AND u.user_id IN (SELECT ui.user_id FROM user_interests ui JOIN controlled_vocab_entry_settings cves ON (ui.controlled_vocab_entry_id = cves.controlled_vocab_entry_id) WHERE cves.setting_name = \'interest\' AND LOWER(cves.setting_value) = ?)', count($interests)) .
				($name !== null?' AND (u.first_name LIKE ? OR u.middle_name LIKE ? OR u.last_name LIKE ? OR u.username LIKE ? OR u.email LIKE ?)':'') . '
			GROUP BY u.user_id
			HAVING 1=1' .
				($doneMin !== null?' AND COUNT(DISTINCT rac.review_id) >= ?':'') .
				($doneMax !== null?' AND COUNT(DISTINCT rac.review_id) <= ?':'') .
				($avgMin !== null?" AND AVG($dateDiffClause) >= ?":'') .
				($avgMax !== null?" AND AVG($dateDiffClause) <= ?":'') .
				($activeMin !== null?' AND COUNT(DISTINCT rai.review_id) >= ?':'') .
				($activeMax !== null?' AND COUNT(DISTINCT rai.review_id) <= ?':'') .
				($lastMin !== null?' AND MAX(raf.date_assigned) <= ' . ($this->datetimeToDB(time() - ((int) $lastMin * 86400))):'') .

What do those tables look like?

Glauco_Roberto_Munsb · May 24, 2017, 1:15pm

Hi @ctgraham, in user_user_groups I have 35326 registers and user_group_stage 66

so in user_interests 8770 registers and 103394 in controlled_vocab_entry_settings

I guess that problem is on PHP array manipulation, because the search at database is fast, but when searching by OJS the query is slow. It is possible?

ctgraham · May 24, 2017, 5:30pm

In your use-case, how many interests are being passed into this function? The PHP array iteration should only traverse count($interests).

Glauco_Roberto_Munsb · May 25, 2017, 12:10am

@ctgraham is 0 on apache log. Below you can see the exact query that was assembled
> SELECT u.*,

COUNT(DISTINCT rac.review_id) AS complete_count,
AVG(DATEDIFF(rac.date_completed, rac.date_notified)) AS average_time,
MAX(raf.date_assigned) AS last_assigned,
COUNT(DISTINCT rai.review_id) AS incomplete_count
FROM users u
JOIN user_user_groups uug ON (uug.user_id = u.user_id)
JOIN user_groups ug ON (ug.user_group_id = uug.user_group_id AND ug.role_id = ? AND ug.context_id = ?)
JOIN user_group_stage ugs ON (ugs.user_group_id = ug.user_group_id AND ugs..stage_id = ?)
LEFT JOIN review_assignments ras ON (ras.submission_id = ? AND ras.stage_id = ?  AND ras.review_round_id = ? AND ras.reviewer_id=u.user_id)
LEFT JOIN review_assignments rac ON (rac.reviewer_id = u.user_id AND rac.date_notified IS NOT NULL AND rac.date_completed IS NOT NULL)
LEFT JOIN review_assignments raf ON (raf.reviewer_id = u.user_id)
LEFT JOIN review_assignments ran ON (ran.reviewer_id = u.user_id AND ran.review_id > raf.review_id)
LEFT JOIN review_assignments rai ON (rai.reviewer_id = u.user_id AND rai.date_notified IS NOT NULL AND rai.date_completed IS NULL AND rai.cancelled = 0 AND rai.declined = 0 AND rai.replaced = 0)
WHERE ras.review_id IS NULL
AND ran.review_id IS NULL
GROUP BY u.user_id
HAVING 1=1 ORDER BY last_name, first_name

After this message the next error is PHP Warning: Cannot use a scalar value as an array in lib/pkp/classes/core/DataObject.inc.php on line 133. Only this.

ctgraham · May 25, 2017, 12:31pm

If you run that exact query in mysql directly (providing parameters they would have been provided in the web run), does it run in reasonable time? I’m going to guess so, since you ran it earlier with no parameters in less than 2 seconds.

If that is the case, I suspect we’re looking at the wrong source for the 90 second timeout.

How are you with PHP? Would you be able to step through the code to see where the long process comes into play?

I was thinking the timeout would be found between the start and completion of this function, but you might prove otherwise:

github.com

pkp/pkp-lib/blob/044e0697ee305a84ff2deb6a921328a8e68dba8e/controllers/grid/users/reviewerSelect/ReviewerSelectGridHandler.inc.php#L163-L198


	/**
	 * @copydoc GridHandler::loadData()
	 */
	protected function loadData($request, $filter) {
		$interests = (array) $filter['interestSearchKeywords'];
		$reviewerValues = $filter['reviewerValues'];

		// Retrieve the authors associated with this submission to be displayed in the grid
		$name = $reviewerValues['name'];
		$doneEnabled = $reviewerValues['doneEnabled'];
		$doneMin = $doneEnabled ? $reviewerValues['doneMin'] : null;
		$doneMax = $doneEnabled ? $reviewerValues['doneMax'] : null;
		$avgEnabled = $reviewerValues['avgEnabled'];
		$avgMin = $avgEnabled ? $reviewerValues['avgMin'] : null;
		$avgMax = $avgEnabled ? $reviewerValues['avgMax'] : null;
		$lastEnabled = $reviewerValues['lastEnabled'];
		$lastMin = $lastEnabled ? $reviewerValues['lastMin'] : null;
		$lastMax = $lastEnabled ? $reviewerValues['lastMax'] : null;
		$activeEnabled = $reviewerValues['activeEnabled'];
		$activeMin = $activeEnabled ? $reviewerValues['activeMin'] : null;

This file has been truncated. show original

Glauco_Roberto_Munsb · May 26, 2017, 11:51am

Hi @ctgraham the question is: In MySQL run less that 2 seconds. But not in PHP/OJS. So a put logs in loadData too, but the process broken after end of the execute $this->retrieveRange in PKPUserDAO.inc.php not after. Coding in PHP is easy to me, I guess, but is not true to OJS structure.
@ctgraham do you think that have another simple way to, por exemple, overwrite this query? Because my journals are stopped and the submissions can’t be sent to our reviewers.

Glauco_Roberto_Munsb · May 28, 2017, 10:43pm

@ctgraham we have a simple way to solve or change this without block the process on jornal?

Glauco_Roberto_Munsb · May 30, 2017, 10:27pm

@asmecher and @ctgraham using in my computer a reply of system the result was not different: It’s a problem in OJS not in my host. 4min to execute the reviewer-select on my computer with 8Gb, SSD and a 5i. I can do something to decrease the execution on this case?

asmecher · May 30, 2017, 10:43pm

Hi @Glauco_Roberto_Munsb,

The MySQL slow query log would be really helpful here to ensure that the query you’re debugging is in fact the problematic one.

Regards,
Alec Smecher
Public Knowledge Project Team