Page MenuHomePhabricator

Daemon worker queue not working
Closed, ResolvedPublic

Description

The daemon queue doesn't seem to be working. It looks like ti was broken by D10766.

Specifically, I have ~200k PhabricatorSearchWorker tasks that are not being processed (even though there are no other tasks in queue). Running a taskmaster daemon in debug mode yields the followign output:

> sudo ./bin/phd debug task
Launching daemon "PhabricatorTaskmasterDaemon" in debug mode (not daemonized).

    phabricator/scripts/daemon/ $ ./phd-daemon 'PhabricatorTaskmasterDaemon' --trace --verbose --phd='/var/run/phd/pid' 

Bringing daemon 'PhabricatorTaskmasterDaemon' online...
>>> [2] <event> daemon.didLaunch <listeners = 2>
>>> [3] <connect> phabricator_daemon
<<< [3] <connect> 4,513 us
>>> [4] <query> INSERT INTO `daemon_log` (`daemon`, `host`, `pid`, `argv`, `explicitArgv`, `envHash`, `status`, `dateCreated`, `dateModified`) VALUES ('PhabricatorTaskmasterDaemon', 'ip-10-125-77-153', '29113', '[\"PhabricatorTaskmasterDaemon\",\"--load-phutil-library=\\/usr\\/src\\/arcanist\\/src\",\"--load-phutil-library=\\/usr\\/src\\/phabricator\\/src\",\"--trace\",\"--verbose\",\"--phd=\\/var\\/run\\/phd\\/pid\"]', '[]', '82c010b4cd4371ab45f4eafe8678169de4121322', 'run', '1415001103', '1415001103')
<<< [4] <query> 1,273 us
<<< [2] <event> 12,392 us
2014-11-03 6:51:43 PM [INIT] Starting process.
>>> [5] <event> daemon.didLogMessage <listeners = 2>
>>> [6] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'INIT', 'Starting process.', '1415001103')
<<< [6] <query> 1,093 us
<<< [5] <event> 2,022 us
>>> [7] <exec> $ exec ./exec_daemon.php 'PhabricatorTaskmasterDaemon' '--trace' '--load-phutil-library=/usr/src/arcanist/src' '--load-phutil-library=/usr/src/phabricator/src' '--verbose' --
2014-11-03 6:51:44 PM [STDE] >>> [0] <connect> phabricator_config
<<< [0] <connect> 6,783 us
>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = 'default' AND isDeleted = 0 
<<< [1] <query> 1,289 us
>>> [2] <connect> phabricator_worker
<<< [2] <connect> 8,084 us
>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1
>>> [8] <event> daemon.didLogMessage <listeners = 2>
>>> [9] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '>>> [0] <connect> phabricator_config\n<<< [0] <connect> 6,783 us\n>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = \'default\' AND isDeleted = 0 \n<<< [1] <query> 1,289 us\n>>> [2] <connect> phabricator_worker\n<<< [2] <connect> 8,084 us\n>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1', '1415001104')
<<< [9] <query> 1,469 us
<<< [8] <event> 2,461 us
2014-11-03 6:51:45 PM [STDE] <<< [3] <query> 1,754,166 us
>>> [4] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '29115:1415001104:ip-10-125-77-153:1', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (14164991))
<<< [4] <query> 1,405 us
>>> [5] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC LIMIT 1
<<< [5] <query> 1,278 us
>>> [10] <event> daemon.didLogMessage <listeners = 2>
>>> [11] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '<<< [3] <query> 1,754,166 us\n>>> [4] <query> UPDATE `worker_activetask` task\n              SET leaseOwner = \'29115:1415001104:ip-10-125-77-153:1\', leaseExpires = UNIX_TIMESTAMP() + 7200\n              WHERE (leaseOwner IS NULL) AND (id IN (14164991))\n<<< [4] <query> 1,405 us\n>>> [5] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC LIMIT
<<< [11] <query> 1,446 us
<<< [10] <event> 2,413 us
2014-11-03 6:51:46 PM [STDE] >>> [6] <connect> phabricator_worker
<<< [6] <connect> 4,518 us
>>> [7] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1
>>> [12] <event> daemon.didLogMessage <listeners = 2>
>>> [13] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '>>> [6] <connect> phabricator_worker\n<<< [6] <connect> 4,518 us\n>>> [7] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1', '1415001106')
<<< [13] <query> 1,307 us
<<< [12] <event> 2,139 us
2014-11-03 6:51:48 PM [STDE] <<< [7] <query> 1,594,665 us
>>> [8] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '29115:1415001106:ip-10-125-77-153:2', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (14164993))
<<< [8] <query> 3,190 us
>>> [9] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC LIMIT 1
<<< [9] <query> 1,139 us
>>> [14] <event> daemon.didLogMessage <listeners = 2>
>>> [15] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '<<< [7] <query> 1,594,665 us\n>>> [8] <query> UPDATE `worker_activetask` task\n              SET leaseOwner = \'29115:1415001106:ip-10-125-77-153:2\', leaseExpires = UNIX_TIMESTAMP() + 7200\n              WHERE (leaseOwner IS NULL) AND (id IN (14164993))\n<<< [8] <query> 3,190 us\n>>> [9] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC LIMIT
<<< [15] <query> 1,455 us
<<< [14] <event> 2,287 us
2014-11-03 6:51:50 PM [STDE] >>> [10] <connect> phabricator_worker
<<< [10] <connect> 14,273 us
>>> [11] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1
>>> [16] <event> daemon.didLogMessage <listeners = 2>
>>> [17] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '>>> [10] <connect> phabricator_worker\n<<< [10] <connect> 14,273 us\n>>> [11] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1', '1415001110')
<<< [17] <query> 1,403 us
<<< [16] <event> 2,245 us
2014-11-03 6:51:52 PM [STDE] <<< [11] <query> 2,086,992 us
>>> [12] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '29115:1415001110:ip-10-125-77-153:3', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (14164995))
<<< [12] <query> 1,312 us
>>> [13] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC LIMIT 1
<<< [13] <query> 1,168 us
>>> [18] <event> daemon.didLogMessage <listeners = 2>
>>> [19] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '<<< [11] <query> 2,086,992 us\n>>> [12] <query> UPDATE `worker_activetask` task\n              SET leaseOwner = \'29115:1415001110:ip-10-125-77-153:3\', leaseExpires = UNIX_TIMESTAMP() + 7200\n              WHERE (leaseOwner IS NULL) AND (id IN (14164995))\n<<< [12] <query> 1,312 us\n>>> [13] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC L
<<< [19] <query> 1,245 us
<<< [18] <event> 2,200 us
2014-11-03 6:51:55 PM [STDE] >>> [14] <connect> phabricator_worker
<<< [14] <connect> 5,028 us
>>> [15] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1
>>> [20] <event> daemon.didLogMessage <listeners = 2>
>>> [21] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '>>> [14] <connect> phabricator_worker\n<<< [14] <connect> 5,028 us\n>>> [15] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1', '1415001115')
<<< [21] <query> 1,250 us
<<< [20] <event> 2,000 us
2014-11-03 6:51:57 PM [STDE] <<< [15] <query> 1,998,334 us
>>> [16] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '29115:1415001115:ip-10-125-77-153:4', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (14164999))
<<< [16] <query> 1,590 us
>>> [17] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC LIMIT 1
<<< [17] <query> 1,172 us
>>> [22] <event> daemon.didLogMessage <listeners = 2>
>>> [23] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '<<< [15] <query> 1,998,334 us\n>>> [16] <query> UPDATE `worker_activetask` task\n              SET leaseOwner = \'29115:1415001115:ip-10-125-77-153:4\', leaseExpires = UNIX_TIMESTAMP() + 7200\n              WHERE (leaseOwner IS NULL) AND (id IN (14164999))\n<<< [16] <query> 1,590 us\n>>> [17] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseExpires < UNIX_TIMESTAMP()) ORDER BY leaseExpires ASC L
<<< [23] <query> 1,230 us
<<< [22] <event> 2,130 us
^C2014-11-03 6:52:01 PM [DONE] Graceful shutdown in response to signal 2 (SIGINT).
>>> [24] <event> daemon.didLogMessage <listeners = 2>
>>> [25] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'DONE', '(2) Graceful shutdown in response to signal 2 (SIGINT).', '1415001121')
<<< [25] <query> 1,411 us
<<< [24] <event> 2,234 us
2014-11-03 6:52:01 PM [STDE] >>> [18] <connect> phabricator_worker
<<< [18] <connect> 4,814 us
>>> [19] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1
>>> [26] <event> daemon.didLogMessage <listeners = 2>
>>> [27] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'STDE', '>>> [18] <connect> phabricator_worker\n<<< [18] <connect> 4,814 us\n>>> [19] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority DESC, id ASC LIMIT 1', '1415001121')
<<< [27] <query> 3,037 us
<<< [26] <event> 4,171 us
^C2014-11-03 6:52:03 PM [EXIT] Shutting down in response to signal 2 (SIGINT).
>>> [28] <event> daemon.didLogMessage <listeners = 2>
>>> [29] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2577', 'EXIT', '(2) Shutting down in response to signal 2 (SIGINT).', '1415001123')
<<< [29] <query> 1,445 us
<<< [28] <event> 2,460 us

After reverting rP914b8bb32cd790ef80484fee8c38f4135c97c849, things seem to be working as expected:

sudo ./bin/phd debug task
Launching daemon "PhabricatorTaskmasterDaemon" in debug mode (not daemonized).

    phabricator/scripts/daemon/ $ ./phd-daemon 'PhabricatorTaskmasterDaemon' --trace --verbose --phd='/var/run/phd/pid' 

Bringing daemon 'PhabricatorTaskmasterDaemon' online...
>>> [2] <event> daemon.didLaunch <listeners = 2>
>>> [3] <connect> phabricator_daemon
<<< [3] <connect> 7,349 us
>>> [4] <query> INSERT INTO `daemon_log` (`daemon`, `host`, `pid`, `argv`, `explicitArgv`, `envHash`, `status`, `dateCreated`, `dateModified`) VALUES ('PhabricatorTaskmasterDaemon', 'ip-10-125-77-153', '30558', '[\"PhabricatorTaskmasterDaemon\",\"--load-phutil-library=\\/usr\\/src\\/arcanist\\/src\",\"--load-phutil-library=\\/usr\\/src\\/phabricator\\/src\",\"--trace\",\"--verbose\",\"--phd=\\/var\\/run\\/phd\\/pid\"]', '[]', '82c010b4cd4371ab45f4eafe8678169de4121322', 'run', '1415001252', '1415001252')
<<< [4] <query> 3,151 us
<<< [2] <event> 17,051 us
2014-11-03 6:54:12 PM [INIT] Starting process.
>>> [5] <event> daemon.didLogMessage <listeners = 2>
>>> [6] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('2578', 'INIT', 'Starting process.', '1415001252')
<<< [6] <query> 1,118 us
<<< [5] <event> 2,112 us
>>> [7] <exec> $ exec ./exec_daemon.php 'PhabricatorTaskmasterDaemon' '--trace' '--load-phutil-library=/usr/src/arcanist/src' '--load-phutil-library=/usr/src/phabricator/src' '--verbose' --
2014-11-03 6:54:13 PM [STDE] >>> [0] <connect> phabricator_config
<<< [0] <connect> 6,846 us
>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = 'default' AND isDeleted = 0 
<<< [1] <query> 4,568 us
>>> [2] <connect> phabricator_worker
<<< [2] <connect> 4,852 us
>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY id ASC LIMIT 1
<<< [3] <query> 1,354 us
>>> [4] <query> UPDATE `worker_activetask` task
            SET leaseOwner = '30560:1415001252:ip-10-125-77-153:1', leaseExpires = UNIX_TIMESTAMP() + 7200
            WHERE (leaseOwner IS NULL) AND (id IN (14165087))
<<< [4] <query> 1,898 us
>>> [5] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE leaseOwner = '30560:1415001252:ip-10-125-77-153:1' AND leaseExpires > UNIX_TIMESTAMP()
        ORDER BY id ASC LIMIT 1
<<< [5] <query> 1,338 us
<VERB> PhabricatorTaskmasterDaemon Working on task 14165087 (PhabricatorSearchWorker)...
>>> [6] <connect> phabricator_maniphest
<<< [6] <connect> 4,735 us
>>> [7] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-cswo5y7bn7whzd3sbibe'))   ORDER BY task.dateModified DESC 
<<< [7] <query> 1,399 us
>>> [8] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-cswo5y7bn7whzd3sbibe')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [8] <query> 1,275 us
>>> [9] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-cswo5y7bn7whzd3sbibe')) ORDER BY id ASC 
<<< [9] <query> 1,753 us
>>> [10] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-cswo5y7bn7whzd3sbibe'))   ORDER BY task.dateModified DESC 
<<< [10] <query> 1,108 us
>>> [11] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-cswo5y7bn7whzd3sbibe')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [11] <query> 1,013 us
>>> [12] <connect> phabricator_user
<<< [12] <connect> 4,439 us
>>> [13] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-32e5ggs2g637oz2tk4xm', 'PHID-USER-dkvyn7h32l5ox2iwxogj', 'PHID-USER-uiziozophylv3v3nw7on', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-e7b7mpzuqonxrertyav6', 'PHID-USER-abzwhc667osh5mwd4gk7'))  ORDER BY user.id DESC 
<<< [13] <query> 1,712 us
>>> [14] <connect> phabricator_file
<<< [14] <connect> 4,412 us
>>> [15] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-b4i3p3daxi7i7i4phwep', 'PHID-FILE-gwiseu6t6nvjeaqpqvbv', 'PHID-FILE-kbbjk37hizikxhmuax7p')) ORDER BY f.id DESC 
<<< [15] <query> 1,096 us
>>> [16] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-b4i3p3daxi7i7i4phwep', 'PHID-FILE-gwiseu6t6nvjeaqpqvbv', 'PHID-FILE-kbbjk37hizikxhmuax7p')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [16] <query> 1,033 us
>>> [17] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-b4i3p3daxi7i7i4phwep', 'PHID-FILE-gwiseu6t6nvjeaqpqvbv', 'PHID-FILE-kbbjk37hizikxhmuax7p') 
<<< [17] <query> 1,026 us
>>> [18] <connect> phabricator_calendar
<<< [18] <connect> 4,724 us
>>> [19] <query> SELECT * FROM `calendar_event` WHERE userPHID IN ('PHID-USER-e7b7mpzuqonxrertyav6', 'PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-dkvyn7h32l5ox2iwxogj', 'PHID-USER-uiziozophylv3v3nw7on', 'PHID-USER-32e5ggs2g637oz2tk4xm', 'PHID-USER-abzwhc667osh5mwd4gk7') AND UNIX_TIMESTAMP() BETWEEN dateFrom AND dateTo 
<<< [19] <query> 1,408 us
>>> [20] <connect> phabricator_project
<<< [20] <connect> 4,375 us
>>> [21] <query> SELECT p.* , vm.dst viewerIsMember FROM `project` p LEFT JOIN `edge` vm ON vm.src = p.phid AND vm.type = 13 AND vm.dst = ''  WHERE (phid IN ('PHID-PROJ-xupjflztscet5ftfipe5'))  ORDER BY name ASC 
<<< [21] <query> 1,101 us
>>> [22] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-dwbou5ugrxzzh7gmc6os')) ORDER BY f.id DESC 
<<< [22] <query> 1,079 us
>>> [23] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-dwbou5ugrxzzh7gmc6os')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [23] <query> 1,055 us
>>> [24] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-dwbou5ugrxzzh7gmc6os') 
<<< [24] <query> 992 us
>>> [25] <connect> phabricator_differential
<<< [25] <connect> 4,463 us
>>> [26] <query> (SELECT r.* FROM `differential_revision` r  WHERE (r.phid IN ('PHID-DREV-w4pvxrxainvky2m7k3kf'))  ORDER BY r.dateModified DESC )
<<< [26] <query> 1,405 us
>>> [27] <connect> phabricator_repository
<<< [27] <connect> 4,265 us
>>> [28] <query> SELECT * FROM `repository` r  WHERE (r.phid IN ('PHID-REPO-e7qvu3z7a3uhk7akjy7y')) ORDER BY r.id DESC 
<<< [28] <query> 1,110 us
>>> [29] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-32e5ggs2g637oz2tk4xm', 'PHID-USER-dkvyn7h32l5ox2iwxogj', 'PHID-USER-uiziozophylv3v3nw7on', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-mq2elk62yb57kg4v77lu'))  ORDER BY user.id DESC 
<<< [29] <query> 2,735 us
>>> [30] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-b4i3p3daxi7i7i4phwep', 'PHID-FILE-gwiseu6t6nvjeaqpqvbv')) ORDER BY f.id DESC 
<<< [30] <query> 1,103 us
>>> [31] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-b4i3p3daxi7i7i4phwep', 'PHID-FILE-gwiseu6t6nvjeaqpqvbv')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [31] <query> 1,003 us
>>> [32] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-b4i3p3daxi7i7i4phwep', 'PHID-FILE-gwiseu6t6nvjeaqpqvbv') 
<<< [32] <query> 1,016 us
>>> [33] <query> SELECT * FROM `calendar_event` WHERE userPHID IN ('PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-dkvyn7h32l5ox2iwxogj', 'PHID-USER-uiziozophylv3v3nw7on', 'PHID-USER-32e5ggs2g637oz2tk4xm') AND UNIX_TIMESTAMP() BETWEEN dateFrom AND dateTo 
<<< [33] <query> 1,332 us
>>> [34] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-cswo5y7bn7whzd3sbibe'))   ORDER BY task.dateModified DESC 
<<< [34] <query> 1,088 us
>>> [35] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-cswo5y7bn7whzd3sbibe')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [35] <query> 1,008 us
>>> [36] <query> SELECT * FROM `maniphest_customfieldstorage` WHERE objectPHID = 'PHID-TASK-cswo5y7bn7whzd3sbibe' AND fieldIndex IN ('.yVmOvBP2a94') 
<<< [36] <query> 1,413 us
>>> [37] <connect> phabricator_search
<<< [37] <connect> 4,420 us
>>> [38] <query> REPLACE INTO `search_document` (`documentType`, `documentTitle`, `documentCreated`, `documentModified`, `phid`) VALUES ('TASK', '[Hire me][Add files] Bar is missing when user is attaching a file with a long name.', '1398673302', '1402622476', 'PHID-TASK-cswo5y7bn7whzd3sbibe')
<<< [38] <query> 6,731 us
>>> [39] <query> DELETE FROM `search_documentfield` WHERE phid = 'PHID-TASK-cswo5y7bn7whzd3sbibe'
<<< [39] <query> 2,473 us
>>> [40] <query> INSERT INTO `search_documentfield` (phid, phidType, field, auxPHID, corpus)  VALUES ('PHID-TASK-cswo5y7bn7whzd3sbibe', 'TASK', 'titl', NULL, '[Hire me][Add files] Bar is missing when user is attaching a file with a long name.')
<<< [40] <query> 1,494 us
>>> [41] <query> INSERT INTO `search_documentfield` (phid, phidType, field, auxPHID, corpus)  VALUES ('PHID-TASK-cswo5y7bn7whzd3sbibe', 'TASK', 'body', NULL, 'URL: www.freelancer.com/freelancers/\n\nBrowser: GC\n\nProcedure:\n1. Go to URL\n2. Click Hire Me\n3. Attach a file with a long file name.\n\nExpected Result:\n{F38143}\n\nActual Result:\n{F38145}\nThe bar is missing when user is attaching a file with a long name.')
<<< [41] <query> 1,878 us
>>> [42] <query> DELETE FROM `search_documentrelationship` WHERE phid = 'PHID-TASK-cswo5y7bn7whzd3sbibe'
<<< [42] <query> 1,453 us
>>> [43] <query> INSERT INTO `search_documentrelationship` (phid, relatedPHID, relation, relatedType, relatedTime)  VALUES ('PHID-TASK-cswo5y7bn7whzd3sbibe', 'PHID-USER-wbhzxymfrs7d7htnc2ky', 'auth', 'USER', 1398673302), ('PHID-TASK-cswo5y7bn7whzd3sbibe', 'PHID-TASK-cswo5y7bn7whzd3sbibe', 'open', 'TASK', 1415001252), ('PHID-TASK-cswo5y7bn7whzd3sbibe', 'PHID-PROJ-xupjflztscet5ftfipe5', 'proj', 'PROJ', 1402622476), ('PHID-TASK-cswo5y7bn7whzd3sbibe', 'PHID-USER-e7b7mpzuqonxrertyav6', 'ownr', 'USER', 1415001252), ('PHID-TASK-cs
<<< [43] <query> 1,466 us
>>> [44] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-cswo5y7bn7whzd3sbibe'))   ORDER BY task.dateModified DESC 
<<< [44] <query> 1,112 us
>>> [45] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-cswo5y7bn7whzd3sbibe')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [45] <query> 989 us
>>> [46] <event> search.didUpdateIndex <listeners = 2>
<<< [46] <event> 211 us
>>> [47] <query> START TRANSACTION
<<< [47] <query> 978 us
>>> [48] <query> DELETE FROM `worker_activetask` WHERE id = 14165087
<<< [48] <query> 7,879 us
>>> [49] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `id`, `dateCreated`, `dateModified`) VALUES ('218080', '0', 'PhabricatorSearchWorker', '30560:1415001252:ip-10-125-77-153:1', '1415008452', '0', '14194432', '1000', '14165087', '1415001252', '1415001252')
<<< [49] <query> 1,225 us
>>> [50] <query> COMMIT
<<< [50] <query> 1,019 us
<VERB> PhabricatorTaskmasterDaemon Task 14165087 complete! Moved to archive.
>>> [51] <connect> phabricator_worker
<<< [51] <connect> 4,498 us
>>> [52] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY id ASC LIMIT 1
<<< [52] <query> 1,253 us
>>> [53] <query> UPDATE `worker_activetask` task
            SET leaseOwner = '30560:1415001252:ip-10-125-77-153:2', leaseExpires = UNIX_TIMESTAMP() + 7200
            WHERE (leaseOwner IS NULL) AND (id IN (14165088))
<<< [53] <query> 1,659 us
>>> [54] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE leaseOwner = '30560:1415001252:ip-10-125-77-153:2' AND leaseExpires > UNIX_TIMESTAMP()
        ORDER BY id ASC LIMIT 1
<<< [54] <query> 3,232 us
<VERB> PhabricatorTaskmasterDaemon Working on task 14165088 (PhabricatorSearchWorker)...
>>> [55] <connect> phabricator_maniphest
<<< [55] <connect> 59,611 us
>>> [56] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-w7i4czfwytem2uhealoy'))   ORDER BY task.dateModified DESC 
<<< [56] <query> 1,425 us
>>> [57] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-w7i4czfwytem2uhealoy')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [57] <query> 1,327 us
>>> [58] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-w7i4czfwytem2uhealoy')) ORDER BY id ASC 
<<< [58] <query> 7,322 us
>>> [59] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-w7i4czfwytem2uhealoy'))   ORDER BY task.dateModified DESC 
<<< [59] <query> 1,141 us
>>> [60] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-w7i4czfwytem2uhealoy')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [60] <query> 1,029 us
>>> [61] <connect> phabricator_user
<<< [61] <connect> 4,616 us
>>> [62] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-bvfbds7pwtdmyk33sc7w', 'PHID-USER-xrrtim3i5bf6s4pm7sfq', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-i3azangastd2oxl6c55f', 'PHID-USER-6epzat4r4whx2y2ddvig', 'PHID-USER-ymlp5ttdz3njjqk6blqj', 'PHID-USER-3vfbpapzqwf6mx3fki42', 'PHID-USER-jl5xbv5js4uwg7yyfwc4', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-hq555jlkdqqruoesgaaw', 'PHID-USER-qdiqvqibolvhnc2a2hqr', 'PHID-USER-h2765fhbbgbldcxwf6an', 'PHID-USER-l4d6bdgqoly
<<< [62] <query> 4,321 us
>>> [63] <connect> phabricator_file
<<< [63] <connect> 4,637 us
>>> [64] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-umcq2akkjhjpq5opkkek', 'PHID-FILE-mkg4bkuqxlipdv56wx7b', 'PHID-FILE-ybw3l24vjybhpjiamg3q', 'PHID-FILE-nhp2czwq6n7bl4uj5h52', 'PHID-FILE-3lyrw7ofqpoubxs7ilav', 'PHID-FILE-r7niacxz36oenw7cki6u')) ORDER BY f.id DESC 
<<< [64] <query> 1,171 us
>>> [65] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-ybw3l24vjybhpjiamg3q', 'PHID-FILE-3lyrw7ofqpoubxs7ilav', 'PHID-FILE-nhp2czwq6n7bl4uj5h52', 'PHID-FILE-r7niacxz36oenw7cki6u', 'PHID-FILE-umcq2akkjhjpq5opkkek', 'PHID-FILE-mkg4bkuqxlipdv56wx7b')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [65] <query> 1,083 us
>>> [66] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-ybw3l24vjybhpjiamg3q', 'PHID-FILE-3lyrw7ofqpoubxs7ilav', 'PHID-FILE-nhp2czwq6n7bl4uj5h52', 'PHID-FILE-r7niacxz36oenw7cki6u', 'PHID-FILE-umcq2akkjhjpq5opkkek', 'PHID-FILE-mkg4bkuqxlipdv56wx7b') 
<<< [66] <query> 1,065 us
>>> [67] <connect> phabricator_calendar
<<< [67] <connect> 4,545 us
>>> [68] <query> SELECT * FROM `calendar_event` WHERE userPHID IN ('PHID-USER-hq555jlkdqqruoesgaaw', 'PHID-USER-bvfbds7pwtdmyk33sc7w', 'PHID-USER-6epzat4r4whx2y2ddvig', 'PHID-USER-ymlp5ttdz3njjqk6blqj', 'PHID-USER-i3azangastd2oxl6c55f', 'PHID-USER-qdiqvqibolvhnc2a2hqr', 'PHID-USER-jl5xbv5js4uwg7yyfwc4', 'PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-3vfbpapzqwf6mx3fki42', 'PHID-USER-ariwvyldrmwqpyg5qjwy', 'PHID-USER-h2765fhbbgbldcxwf6an', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-l4d6bdgqo
<<< [68] <query> 1,431 us
>>> [69] <connect> phabricator_project
<<< [69] <connect> 4,264 us
>>> [70] <query> SELECT p.* , vm.dst viewerIsMember FROM `project` p LEFT JOIN `edge` vm ON vm.src = p.phid AND vm.type = 13 AND vm.dst = ''  WHERE (phid IN ('PHID-PROJ-xupjflztscet5ftfipe5', 'PHID-PROJ-qrl4qp5yxspvlhpcxom3'))  ORDER BY name ASC 
<<< [70] <query> 1,080 us
>>> [71] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-dwbou5ugrxzzh7gmc6os', 'PHID-FILE-rjiqlcdkn4lnhkayhfdq')) ORDER BY f.id DESC 
<<< [71] <query> 1,153 us
>>> [72] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-rjiqlcdkn4lnhkayhfdq', 'PHID-FILE-dwbou5ugrxzzh7gmc6os')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [72] <query> 1,040 us
>>> [73] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-rjiqlcdkn4lnhkayhfdq', 'PHID-FILE-dwbou5ugrxzzh7gmc6os') 
<<< [73] <query> 1,044 us
>>> [74] <connect> phabricator_differential
<<< [74] <connect> 4,548 us
>>> [75] <query> (SELECT r.* FROM `differential_revision` r  WHERE (r.phid IN ('PHID-DREV-jizt3lx7vgkbeeag3igo'))  ORDER BY r.dateModified DESC )
<<< [75] <query> 1,419 us
>>> [76] <connect> phabricator_repository
<<< [76] <connect> 4,215 us
>>> [77] <query> SELECT * FROM `repository` r  WHERE (r.phid IN ('PHID-REPO-e7qvu3z7a3uhk7akjy7y')) ORDER BY r.id DESC 
<<< [77] <query> 1,077 us
>>> [78] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-bvfbds7pwtdmyk33sc7w', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-i3azangastd2oxl6c55f', 'PHID-USER-6epzat4r4whx2y2ddvig', 'PHID-USER-ymlp5ttdz3njjqk6blqj', 'PHID-USER-3vfbpapzqwf6mx3fki42', 'PHID-USER-jl5xbv5js4uwg7yyfwc4', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-hq555jlkdqqruoesgaaw', 'PHID-USER-qdiqvqibolvhnc2a2hqr', 'PHID-USER-h2765fhbbgbldcxwf6an', 'PHID-USER-l4d6bdgqolyfk6lorhjl', 'PHID-USER-ariwvyldrmw
<<< [78] <query> 2,467 us
>>> [79] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-umcq2akkjhjpq5opkkek', 'PHID-FILE-mkg4bkuqxlipdv56wx7b', 'PHID-FILE-ybw3l24vjybhpjiamg3q', 'PHID-FILE-nhp2czwq6n7bl4uj5h52', 'PHID-FILE-3lyrw7ofqpoubxs7ilav', 'PHID-FILE-r7niacxz36oenw7cki6u')) ORDER BY f.id DESC 
<<< [79] <query> 1,293 us
>>> [80] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-ybw3l24vjybhpjiamg3q', 'PHID-FILE-3lyrw7ofqpoubxs7ilav', 'PHID-FILE-nhp2czwq6n7bl4uj5h52', 'PHID-FILE-r7niacxz36oenw7cki6u', 'PHID-FILE-umcq2akkjhjpq5opkkek', 'PHID-FILE-mkg4bkuqxlipdv56wx7b')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [80] <query> 1,060 us
>>> [81] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-ybw3l24vjybhpjiamg3q', 'PHID-FILE-3lyrw7ofqpoubxs7ilav', 'PHID-FILE-nhp2czwq6n7bl4uj5h52', 'PHID-FILE-r7niacxz36oenw7cki6u', 'PHID-FILE-umcq2akkjhjpq5opkkek', 'PHID-FILE-mkg4bkuqxlipdv56wx7b') 
<<< [81] <query> 1,031 us
>>> [82] <query> SELECT * FROM `calendar_event` WHERE userPHID IN ('PHID-USER-hq555jlkdqqruoesgaaw', 'PHID-USER-bvfbds7pwtdmyk33sc7w', 'PHID-USER-6epzat4r4whx2y2ddvig', 'PHID-USER-ymlp5ttdz3njjqk6blqj', 'PHID-USER-i3azangastd2oxl6c55f', 'PHID-USER-qdiqvqibolvhnc2a2hqr', 'PHID-USER-jl5xbv5js4uwg7yyfwc4', 'PHID-USER-wbhzxymfrs7d7htnc2ky', 'PHID-USER-3vfbpapzqwf6mx3fki42', 'PHID-USER-ariwvyldrmwqpyg5qjwy', 'PHID-USER-h2765fhbbgbldcxwf6an', 'PHID-USER-k2i4mgrjrfiizyplwjyh', 'PHID-USER-mq2elk62yb57kg4v77lu', 'PHID-USER-l4d6bdgqo
<<< [82] <query> 1,464 us
>>> [83] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-w7i4czfwytem2uhealoy'))   ORDER BY task.dateModified DESC 
<<< [83] <query> 1,225 us
>>> [84] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-w7i4czfwytem2uhealoy')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [84] <query> 1,017 us
>>> [85] <query> SELECT * FROM `maniphest_customfieldstorage` WHERE objectPHID = 'PHID-TASK-w7i4czfwytem2uhealoy' AND fieldIndex IN ('.yVmOvBP2a94') 
<<< [85] <query> 1,305 us
>>> [86] <connect> phabricator_search
<<< [86] <connect> 4,352 us
>>> [87] <query> REPLACE INTO `search_document` (`documentType`, `documentTitle`, `documentCreated`, `documentModified`, `phid`) VALUES ('TASK', '[Contest Page][Upgrade Contest] The Upgrade Contest button is not functioning after extending the contest', '1398674376', '1401064757', 'PHID-TASK-w7i4czfwytem2uhealoy')
<<< [87] <query> 1,251 us
>>> [88] <query> DELETE FROM `search_documentfield` WHERE phid = 'PHID-TASK-w7i4czfwytem2uhealoy'
<<< [88] <query> 2,985 us
>>> [89] <query> INSERT INTO `search_documentfield` (phid, phidType, field, auxPHID, corpus)  VALUES ('PHID-TASK-w7i4czfwytem2uhealoy', 'TASK', 'titl', NULL, '[Contest Page][Upgrade Contest] The Upgrade Contest button is not functioning after extending the contest')
<<< [89] <query> 1,389 us
>>> [90] <query> INSERT INTO `search_documentfield` (phid, phidType, field, auxPHID, corpus)  VALUES ('PHID-TASK-w7i4czfwytem2uhealoy', 'TASK', 'body', NULL, 'URL: https://www.test.staging4.freelancer.com/contest/contestname-contestid.html\nBrowser:\nOS: Windows 7 Professional 64-bit\n\nProcedures:\n1. Create a contest with all upgrades selected.\n2. Click the Upgrade Contest button and then extend the contest.\n3. Click again the Upgrade Contest button after extending the contest.\n4. Notice that the Upgrade Contest button
<<< [90] <query> 2,333 us
>>> [91] <query> DELETE FROM `search_documentrelationship` WHERE phid = 'PHID-TASK-w7i4czfwytem2uhealoy'
<<< [91] <query> 5,977 us
>>> [92] <query> INSERT INTO `search_documentrelationship` (phid, relatedPHID, relation, relatedType, relatedTime)  VALUES ('PHID-TASK-w7i4czfwytem2uhealoy', 'PHID-USER-bvfbds7pwtdmyk33sc7w', 'auth', 'USER', 1398674376), ('PHID-TASK-w7i4czfwytem2uhealoy', 'PHID-TASK-w7i4czfwytem2uhealoy', 'clos', 'TASK', 1415001252), ('PHID-TASK-w7i4czfwytem2uhealoy', 'PHID-PROJ-xupjflztscet5ftfipe5', 'proj', 'PROJ', 1401064757), ('PHID-TASK-w7i4czfwytem2uhealoy', 'PHID-PROJ-qrl4qp5yxspvlhpcxom3', 'proj', 'PROJ', 1401064757), ('PHID-TASK-w7
<<< [92] <query> 3,064 us
>>> [93] <query> SELECT task.*   FROM `maniphest_task` task  WHERE (phid in ('PHID-TASK-w7i4czfwytem2uhealoy'))   ORDER BY task.dateModified DESC 
<<< [93] <query> 1,121 us
>>> [94] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-w7i4czfwytem2uhealoy')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [94] <query> 1,003 us
>>> [95] <event> search.didUpdateIndex <listeners = 2>
<<< [95] <event> 190 us
>>> [96] <query> START TRANSACTION
<<< [96] <query> 991 us
>>> [97] <query> DELETE FROM `worker_activetask` WHERE id = 14165088
<<< [97] <query> 1,206 us
>>> [98] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `id`, `dateCreated`, `dateModified`) VALUES ('222789', '0', 'PhabricatorSearchWorker', '30560:1415001252:ip-10-125-77-153:2', '1415008452', '0', '14194433', '1000', '14165088', '1415001252', '1415001252')
<<< [98] <query> 1,132 us
>>> [99] <query> COMMIT
<<< [99] <query> 1,066 us
<VERB> PhabricatorTaskmasterDaemon Task 14165088 complete! Moved to archive.
>>> [100] <connect> phabricator_worker
<<< [100] <connect> 4,674 us

Event Timeline

joshuaspence raised the priority of this task from to High.
joshuaspence updated the task description. (Show Details)
joshuaspence added a project: Phabricator.
joshuaspence added a subscriber: joshuaspence.

I can't reproduce this (we've been running with the patch on this install since shortly after it was committed) and the logs don't make it clear what's wrong -- it looks like the foreground process might have raced with another process and lost?

Hmm, I don't think this is a race condition because none of the tasks are being executed. The queue stayed at ~200k tasks for a few hours.

We also are running the patch and it has been great, could this in some way be related to carry over daemon work from before getting in a weird state? We did carry over a large backlog though during upgrade (500k+) and PhD caught up like a champ so I dont know.

There were two separate patches to the daemons -- I think @joshuaspence was talking about D10766 (affecting the execution order of tasks), not D10895 (affecting performance for large queues).

T6742 is an issue with similar symptoms, but the root cause was the leaseOwner column generating with an overlong string value because of a very verbose hostname. It doesn't look like that was the issue here. We haven't seen any other reports of this specific issue, to my knowledge.

Oh sorry my bad. The context slipped by me.

joshuaspence claimed this task.

Seems to see fixed.