Page MenuHomePhabricator
Create Task
Maniphest T8306

Understanding phd, memory limitations, elasticsearch index slowness
Closed, InvalidPublic
Actions

Description

Below is my cookbook on setting up phabricator and elasticsearch; task data has over 77k tasks entries. It is my assumption and limited understanding that the data from phabricator doesn't get pushed over unless I run daemons (specifically PhabricatorTaskmasterDaemon) even though I manually ran bin/search index but the problem is the daemons consume all 16G of memory and of course this causes very slow or failed webserver response and eventually insert fails as well.

So, what is the correct procedure so can I stop the daemons initially, store/load the data; then force phabricator to trigger data into the queue or whatever magical to pass the indexing over to elasticsearch quickly? My goal is then while in production, stop daemons from running and later possible have a secondary server to handle indexing/inserting batch and another for reading. It seems silly I need a 32G+ Ram Memory or more to handle just less than 100,000 index tasks for searching and retrieval.

The setup will work very slowly. It seems to index but it's super super slow. Meaning it takes close to 1 hour to index just 70 tasks. I feel blind too, because I don't know really how to debug the slowness problem.

So how do I do the following:

  1. clear out the 'index queue'; it seems to build up somewhere and if I recreate ubuntu and copy over db; it doesn't start at T-1., currently working at T31396 and not sure why this is the case.
  2. determine what task(s) it is on for queuing
  3. What logs (commands) allows me to have sight in what is being processed, right now i'm blind with phd start or phd debug <Daemon>
  4. configure index to work faster under the 16G limitation

Below is the suggested configuration values being used; however, I've experimented with the following:
innodb_buffer_pool_size=1600M -> 1200M
max_allowed_packet = 32M -> 30M
(however I don't notice any real changes except maybe a faster response on apache2 pages)

Hardware Configuration

16G Ram Memory
1G SSD
Ubuntu 10.04 x86_64

Software Version

elasticsearch-1.5.2.deb

arcanist
commit 9b7c6786cdc9694b45907ecb46154befbd605a0d
Date: Sun May 24 07:45:01 2015 +1000

libphutil
commit 4e0febf56d83d917558606c06ca72cdc42524566
Date: Sun May 24 06:37:12 2015 -0700

phabricator
commit 18fe6d58aeba41c6ac17e41c6f374ea429668e6a
Date: Sun May 24 11:22:33 2015 -0700

top output before phd

KiB Mem:  16120708 total,  3012396 used, 13108312 free,    42992 buffers
KiB Swap: 16457724 total,  1037176 used, 15420548 free.   801372 cached Mem

max task count

./bin/search init
Index exists but is incorrect, fixing...done.
NOTE: @mapping.json directly copied from {T6552#86240}
bin/phd stop --force
curl -XDELETE http://localhost:9200/phabricator?pretty=1
curl -XPOST 'http://localhost:9200/_optimize?only_expunge_deletes=true'

curl -XDELETE 'http://localhost:9200/_template/template_phabricator'
curl -XPUT 'http://localhost:9200/_template/template_phabricator' -d @mapping.json

curl -XGET http://localhost:9200/phabricator
curl -XGET http://localhost:9200/_aliases?pretty=1

curl http://localhost:9200/_cluster/health?pretty=true

cd /var/www/phabricator

bin/search init
bin/search index --all --background

curl http://localhost:9200/phabricator/_stats?pretty=1
curl http://localhost:9200/_cluster/health?pretty=true
Run this workflow with "--background" to queue tasks for the daemon workers.
Indexing 77281 object of type TASK.
Indexing 94 object of type PROJ.
Indexing 2 object of type USER.
Indexing 1 object of type MOCK.

After completion:

"indices" : {
  "phabricator" : {
    "primaries" : {
      "docs" : {
        "count" : 0,
        "deleted" : 0
      },
      "store" : {
        "size_in_bytes" : 575,
        "throttle_time_in_millis" : 0
      },
      "indexing" : {
        "index_total" : 0,

unresolved issues

  • All other issues are based on phabricator configuration suggestions

pasted_file (554×924 px, 101 KB)

bin/phd start
Freeing active task leases...
Freed 11 task lease(s).
Launching daemons:
(Logs will appear in "/var/tmp/phd/log/daemons.log".)

    PhabricatorRepositoryPullLocalDaemon (Static)
    PhabricatorTriggerDaemon (Static)
    PhabricatorTaskmasterDaemon (Autoscaling: group=task, pool=4, reserve=0)

Done.

top after phd

KiB Mem:  16120708 total,  3293332 used, 12827376 free,   263752 buffers
KiB Swap: 16457724 total,  1775912 used, 14681812 free.   878932 cached Mem

elastic search

After 30 minutes....

"indices" : {
  "phabricator" : {
    "primaries" : {
      "docs" : {
        "count" : 18,
        "deleted" : 9
      },
      "store" : {
        "size_in_bytes" : 207056,
        "throttle_time_in_millis" : 0
      },
      "indexing" : {
        "index_total" : 43,

after 1 hour

"indices" : {
  "phabricator" : {
    "primaries" : {
      "docs" : {
        "count" : 30,
        "deleted" : 16
      },
      "store" : {
        "size_in_bytes" : 323143,
        "throttle_time_in_millis" : 0
      },
      "indexing" : {
        "index_total" : 71,

after 2 hour

"indices" : {
  "phabricator" : {
    "primaries" : {
      "docs" : {
        "count" : 30,
        "deleted" : 16
      },
      "store" : {
        "size_in_bytes" : 323143,
        "throttle_time_in_millis" : 0
      },
      "indexing" : {
        "index_total" : 147,

Related Objects

Event Timeline

JoggerTech created this task.May 25 2015, 5:13 AM
JoggerTech raised the priority of this task from to Needs Triage.
JoggerTech updated the task description. (Show Details)
JoggerTech added a subscriber: JoggerTech.
JoggerTech added a project: Elasticsearch.May 25 2015, 5:15 AM
JoggerTech updated the task description. (Show Details)May 25 2015, 5:18 AM
JoggerTech renamed this task from Understanding phd, memory limitations, elasticsearch to Understanding phd, memory limitations, elasticsearch index slowness.May 25 2015, 6:22 AM
JoggerTech updated the task description. (Show Details)
JoggerTech updated the task description. (Show Details)May 25 2015, 6:36 AM
epriestley added a subscriber: epriestley.May 25 2015, 11:12 AM

These numbers are wildly out of line with expectations. For comparison, I just ran a similar workload on this machine:

$ ./bin/search index --type task --background

We have about 8300 tasks and this took about 11 minutes to run, so each task took about 80ms to queue. Memory usage was not significant (less than 100MB).

The tasks then processed from the queue at a rate of about 7.5/second. We run a standard setup with 4 taskmasters, so this corresponds to roughly 500ms per indexing task. Memory usage was also not significant (about 100MB per taskmaster).

Can you show me the output of this command?

phabricator/ $ time ./bin/search index T123 --trace

...for some arbitrary valid task (not necessarily T123 specifically)? Here's the output on this install, against this task, with the caveat that we're using the MySQL index rather than the ElasticSearch index:

$ time ./bin/search index T8306 --trace
>>> [2] <connect> phabricator_maniphest
<<< [2] <connect> 1,782 us
>>> [3] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.id in (8306))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC 
<<< [3] <query> 631 us
Run this workflow with "--background" to queue tasks for the daemon workers.
Indexing 1 object of type TASK.
>>> [4] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-hgl67pwaeky23wwistcf'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC 
<<< [4] <query> 545 us
>>> [5] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-hgl67pwaeky23wwistcf')) ORDER BY `id` DESC 
<<< [5] <query> 975 us
>>> [6] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-hgl67pwaeky23wwistcf'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC 
<<< [6] <query> 2,317 us
>>> [7] <connect> phabricator_user
<<< [7] <connect> 3,862 us
>>> [8] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-frgicp54xnzv2ukghyjl'))  ORDER BY `user`.`id` DESC 
<<< [8] <query> 581 us
>>> [9] <connect> phabricator_repository
<<< [9] <connect> 9,240 us
>>> [10] <query> SELECT commit.* FROM `repository_commit` commit  WHERE (commit.phid IN ('PHID-CMIT-ftyfdwh2byhzeqvbwcjo', 'PHID-CMIT-egcbvwe2unbh3m5ug5sy', 'PHID-CMIT-lmg5jm5fytams7z3eeek'))  ORDER BY `commit`.`id` DESC 
<<< [10] <query> 669 us
>>> [11] <query> SELECT `r`.* FROM `repository` r  WHERE (r.id IN (5, 3, 2))   ORDER BY `r`.`id` DESC 
<<< [11] <query> 4,634 us
>>> [12] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dp7irqwwsehgduvn3rwo'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC 
<<< [12] <query> 546 us
>>> [13] <connect> phabricator_project
<<< [13] <connect> 4,121 us
>>> [14] <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-cvgyhqrtdkjpzaabfjf7'))  ORDER BY `p`.`name` ASC 
<<< [14] <query> 652 us
>>> [15] <connect> phabricator_file
<<< [15] <connect> 5,447 us
>>> [16] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('PHID-FILE-puhjpp2dtydqoqauqvvl')) ORDER BY `f`.`id` DESC 
<<< [16] <query> 639 us
>>> [17] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-puhjpp2dtydqoqauqvvl')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [17] <query> 674 us
>>> [18] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-puhjpp2dtydqoqauqvvl') 
<<< [18] <query> 528 us
>>> [19] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-hgl67pwaeky23wwistcf'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC 
<<< [19] <query> 540 us
>>> [20] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-hgl67pwaeky23wwistcf')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [20] <query> 2,645 us
>>> [21] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-frgicp54xnzv2ukghyjl'))  ORDER BY `user`.`id` DESC 
<<< [21] <query> 552 us
>>> [22] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-hgl67pwaeky23wwistcf')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [22] <query> 1,338 us
>>> [23] <connect> phabricator_search
<<< [23] <connect> 5,048 us
>>> [24] <query> REPLACE INTO `search_document` (`documentType`, `documentTitle`, `documentCreated`, `documentModified`, `phid`) VALUES ('TASK', 'Understanding phd, memory limitations, elasticsearch index slowness', '1432530782', '1432535819', 'PHID-TASK-hgl67pwaeky23wwistcf')
<<< [24] <query> 2,705 us
>>> [25] <query> DELETE FROM `search_documentfield` WHERE phid = 'PHID-TASK-hgl67pwaeky23wwistcf'
<<< [25] <query> 15,697 us
>>> [26] <query> INSERT INTO `search_documentfield` (phid, phidType, field, auxPHID, corpus) VALUES ('PHID-TASK-hgl67pwaeky23wwistcf', 'TASK', 'titl', NULL, 'Understanding phd, memory limitations, elasticsearch index slowness')
<<< [26] <query> 7,966 us
>>> [27] <query> INSERT INTO `search_documentfield` (phid, phidType, field, auxPHID, corpus) VALUES ('PHID-TASK-hgl67pwaeky23wwistcf', 'TASK', 'body', NULL, 'Below is my cookbook on setting up phabricator and elasticsearch; task data has over 77k tasks entries.  It is my assumption and limited understanding that the data from phabricator doesn\'t get pushed over unless I run daemons (specifically PhabricatorTaskmasterDaemon)  even though I manually ran `bin/search index` but the problem is the daemons consume all 16G of mem
<<< [27] <query> 16,551 us
>>> [28] <query> DELETE FROM `search_documentrelationship` WHERE phid = 'PHID-TASK-hgl67pwaeky23wwistcf'
<<< [28] <query> 5,012 us
>>> [29] <query> INSERT INTO `search_documentrelationship` (phid, relatedPHID, relation, relatedType, relatedTime) VALUES ('PHID-TASK-hgl67pwaeky23wwistcf', 'PHID-USER-frgicp54xnzv2ukghyjl', 'auth', 'USER', 1432530782), ('PHID-TASK-hgl67pwaeky23wwistcf', 'PHID-TASK-hgl67pwaeky23wwistcf', 'open', 'TASK', 1432552263), ('PHID-TASK-hgl67pwaeky23wwistcf', 'PHID-TASK-hgl67pwaeky23wwistcf', 'unow', 'VOID', 1432530782), ('PHID-TASK-hgl67pwaeky23wwistcf', 'PHID-USER-frgicp54xnzv2ukghyjl', 'subs', 'USER', 1432535819), ('PHID-TASK-hgl
<<< [29] <query> 2,065 us
>>> [30] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-hgl67pwaeky23wwistcf'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC 
<<< [30] <query> 3,479 us
>>> [31] <event> search.didUpdateIndex <listeners = 2>
<<< [31] <event> 239 us
>>> [32] <connect> phabricator_worker
<<< [32] <connect> 863 us
>>> [33] <query> START TRANSACTION
<<< [33] <query> 286 us
>>> [34] <query> INSERT INTO `worker_taskdata` (`data`) VALUES ('{\"documentPHID\":\"PHID-TASK-hgl67pwaeky23wwistcf\",\"context\":null}')
<<< [34] <query> 401 us
>>> [35] <query> INSERT INTO `lisk_counter` (counterName, counterValue) VALUES
          ('worker_activetask', LAST_INSERT_ID(1))
        ON DUPLICATE KEY UPDATE
          counterValue = LAST_INSERT_ID(counterValue + 1)
<<< [35] <query> 530 us
>>> [36] <query> INSERT INTO `worker_activetask` (`failureTime`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`) VALUES (NULL, 'PhabricatorSearchWorker', NULL, NULL, '0', '889255', '4000', NULL, '882358')
<<< [36] <query> 452 us
>>> [37] <query> SAVEPOINT Aphront_Savepoint_1
<<< [37] <query> 328 us
>>> [38] <query> DELETE FROM `worker_activetask` WHERE id = 882358
<<< [38] <query> 441 us
>>> [39] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('0', '0', 'PhabricatorSearchWorker', NULL, NULL, '0', '889255', '4000', NULL, '882358', '1432552263', '1432552263')
<<< [39] <query> 445 us
>>> [40] <query> COMMIT
<<< [40] <query> 2,736 us

real	0m0.881s
user	0m0.288s
sys	0m0.116s

Note that the times displayed by --trace are printed incorrectly until rPHU65819efa.

JoggerTech added a comment.May 25 2015, 12:39 PM
> bin/phd status
Log Daemon       Host      Overseer Started                 Class                                Arguments
229 24793:p2icsv localhost 24793    May 25 2015, 6:30:38 AM PhabricatorRepositoryPullLocalDaemon
230 24793:gxho6u localhost 24793    May 25 2015, 6:30:38 AM PhabricatorTriggerDaemon
231 24793:2pttlj localhost 24793    May 25 2015, 6:30:38 AM PhabricatorTaskmasterDaemon
232 24793:ncviya localhost 24793    May 25 2015, 6:30:38 AM PhabricatorTaskmasterDaemon
233 24793:hqcy3p localhost 24793    May 25 2015, 6:30:38 AM PhabricatorTaskmasterDaemon
234 24793:yrrdmd localhost 24793    May 25 2015, 6:30:38 AM PhabricatorTaskmasterDaemon

top

KiB Mem:  16120708 total, 15947620 used,   173088 free,      356 buffers
KiB Swap: 16457724 total, 10183480 used,  6274244 free.   130460 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
25504 root      20   0 13.791g 7.221g    564 D  25.3 47.0   1:25.28 php
24415 mysql     20   0 2556016 1.152g    936 S   8.0  7.5  51:27.65 mysqld
> date;curl http://localhost:9200/phabricator/_stats?pretty=1 | grep index_total

Mon May 25 20:36:34 HKT 2015
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 11773  100 11773    0     0   5859      0  0:00:02  0:00:02 --:--:--  5868
        "index_total" : 726,
>time ./bin/search index T123 --trace
>>> [2] <connect> phabricator_maniphest
<<< [2] <connect> 3 us
>>> [3] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.id in (123))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [3] <query> 311 us
Run this workflow with "--background" to queue tasks for the daemon workers.
Indexing 1 object of type TASK.
>>> [4] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-3tszqlao5b3tocjo7lil'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [4] <query> 474 us
>>> [5] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-3tszqlao5b3tocjo7lil')) ORDER BY `id` DESC
<<< [5] <query> 2 us
>>> [6] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-3tszqlao5b3tocjo7lil'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [6] <query> 1 us
>>> [7] <connect> phabricator_user
<<< [7] <connect> 3 us
>>> [8] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [8] <query> 1 us
>>> [9] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-t3yookharcaprzxmojvn'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [9] <query> 3 us
>>> [10] <connect> phabricator_project
<<< [10] <connect> 6 us
>>> [11] <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-w5pkzjo2azlhtzexxxkh'))  ORDER BY `p`.`name` ASC
<<< [11] <query> 298 us
>>> [12] <connect> phabricator_file
<<< [12] <connect> 26 us
>>> [13] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('')) ORDER BY `f`.`id` DESC
<<< [13] <query> 282 us
>>> [14] <query> SELECT f.* FROM `file` f JOIN `file_transformedfile` t ON t.transformedPHID = f.phid WHERE (((t.originalPHID = 'PHID-VOID-00000000000000000000' AND t.transform = 'builtin:project.png'))) ORDER BY `f`.`id` DESC
<<< [14] <query> 405 us
>>> [15] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-vr6jvlxjfuh2ojmxkqs3')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [15] <query> 511 us
>>> [16] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-vr6jvlxjfuh2ojmxkqs3')
<<< [16] <query> 386 us
>>> [17] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-3tszqlao5b3tocjo7lil'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [17] <query> 357 us
>>> [18] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-3tszqlao5b3tocjo7lil')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [18] <query> 296 us
>>> [19] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [19] <query> 257 us
>>> [20] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-3tszqlao5b3tocjo7lil')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [20] <query> 263 us
>>> [21] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-3tszqlao5b3tocjo7lil'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [21] <query> 1 us
>>> [22] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-3tszqlao5b3tocjo7lil/
<<< [22] <http> 269 us
>>> [23] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-3tszqlao5b3tocjo7lil'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [23] <query> 3 us
>>> [24] <event> search.didUpdateIndex <listeners = 2>
<<< [24] <event> 212 us
>>> [25] <connect> phabricator_worker
<<< [25] <connect> 21 us
>>> [26] <query> START TRANSACTION
<<< [26] <query> 802 us
>>> [27] <query> INSERT INTO `worker_taskdata` (`data`) VALUES ('{\"documentPHID\":\"PHID-TASK-3tszqlao5b3tocjo7lil\",\"context\":null}')
<<< [27] <query> 22 us
>>> [28] <query> INSERT INTO `lisk_counter` (counterName, counterValue) VALUES
          ('worker_activetask', LAST_INSERT_ID(1))
        ON DUPLICATE KEY UPDATE
          counterValue = LAST_INSERT_ID(counterValue + 1)
<<< [28] <query> 34 us
>>> [29] <query> INSERT INTO `worker_activetask` (`failureTime`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`) VALUES (NULL, 'PhabricatorSearchWorker', NULL, NULL, '0', '956335', '4000', NULL, '956337')
<<< [29] <query> 11 us
>>> [30] <query> SAVEPOINT Aphront_Savepoint_1
<<< [30] <query> 4 us
>>> [31] <query> DELETE FROM `worker_activetask` WHERE id = 956337
<<< [31] <query> 527 us
>>> [32] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('0', '0', 'PhabricatorSearchWorker', NULL, NULL, '0', '956335', '4000', NULL, '956337', '1432557295', '1432557295')
<<< [32] <query> 6 us
>>> [33] <query> COMMIT
<<< [33] <query> 15 us

real    0m1.727s
user    0m0.273s
sys     0m0.160s
>date;curl http://localhost:9200/phabricator/_stats?pretty=1 | grep index_total
Mon May 25 20:36:56 HKT 2015
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
        "index_total" : 727,
JoggerTech added a comment.EditedMay 25 2015, 1:07 PM

I did the following:
/bin/phd stop

top

KiB Mem:  16120708 total,  2746472 used, 13374236 free,    44684 buffers
KiB Swap: 16457724 total,  1048052 used, 15409672 free.   815296 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1528 elastic+  20   0 3550388 263908   5800 S   6.0  1.6  17:25.48 java
24415 mysql     20   0 2556016 1.253g   1632 S   2.7  8.2  54:16.05 mysqld

created simple bash program

#!/bin/bash

for incremental in `seq 1 77281`;
do
 echo T$incremental
 ./bin/search index T$incremental
done

After 10 minutes; 2000 indexes were inserted into elasticsearch; therefore, a little more than 7 hour to complete 78,000 indexes; so, why does bin/phd start consume so much ram/swap and why is the daemon so slow to execute the insert queue?

epriestley added a comment.May 25 2015, 1:24 PM

Can you run bin/phd debug taskmaster for a minute or so and show me the output?

JoggerTech added a comment.May 25 2015, 1:41 PM
KiB Mem:  16120708 total, 15954548 used,   166160 free,    50420 buffers
KiB Swap: 16457724 total,  1017324 used, 15440400 free.  2086480 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 5273 root      20   0 11.485g 0.011t   8320 R  94.6 73.1   0:51.66 php

bin/phd debug taskmaster

Launching daemons (in debug mode):
(Logs will appear in "/var/tmp/phd/log/daemons.log".)

    PhabricatorTaskmasterDaemon (Static)


    phabricator/scripts/daemon/ $ ./phd-daemon '--trace' '--verbose'

>>> [2] <event> daemon.didLaunch <listeners = 2>
>>> [3] <connect> phabricator_daemon
<<< [3] <connect> 491 us
>>> [4] <query> INSERT INTO `daemon_log` (`daemon`, `host`, `pid`, `daemonID`, `runningAsUser`, `argv`, `explicitArgv`, `envHash`, `envInfo`, `status`, `dateCreated`, `dateModified`) VALUES ('PhabricatorTaskmasterDaemon', 'ubuntu3', '5260', '5260:venpmdk', 'root', '[\"--trace\",\"--verbose\"]', '[]', '7b83329e6bd120fbb001965e15e69d591c7deae1', '{\"version\":1,\"keys\":\"MJOmom.6GshL\",\"values\":{\"darkconsole.enabled\":\"v.jX3f8wOz8F\",\"metamta.default-address\":\"d5lCyWmwd0Hc\",\"metamta.domain\":\"EQE.ursbVGC_\",\"meta
<<< [4] <query> 5 us
<<< [2] <event> 24 us
2015-05-25 1:35:59 PM [INIT] Starting process.
>>> [5] <event> daemon.didLogMessage <listeners = 2>
>>> [6] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('235', 'INIT', 'Starting process.', '1432560959')
<<< [6] <query> 10 us
<<< [5] <event> 11 us
>>> [7] <exec> $ exec ./exec_daemon.php 'PhabricatorTaskmasterDaemon' '--trace' '--verbose'
2015-05-25 1:36:00 PM [STDE] >>> [0] <connect> phabricator_config
<<< [0] <connect> 2 us
>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = 'default' AND isDeleted = 0
<<< [1] <query> 299 us
>>> [2] <connect> phabricator_worker
<<< [2] <connect> 725 us
>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [3] <query> 6 us
>>> [4] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '5273:1432560959:ubuntu3:1', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363064))
<<< [4] <query> 6 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 task.leaseOwner = '5273:1432560959:ubuntu3:1' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [5] <query> 2 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363064 (PhabricatorSearchWorker)...
>>> [6] <connect> phabricator_maniphest
<<< [6] <connect> 691 us
>>> [7] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-pxcyucr5e3lh3fqfjrpw'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [7] <query> 1 us
>>> [8] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-pxcyucr5e3lh3fqfjrpw')) ORDER BY `id` DESC
<<< [8] <query> 1 us
>>> [9] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-pxcyucr5e3lh3fqfjrpw'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [9] <query> 293 us
>>> [10] <connect> phabricator_user
<<< [10] <connect> 903 us
>>> [11] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [11] <query> 372 us
>>> [12] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-y7knwqu4ixnilrwgbitv', 'PHID-TASK-cmy7zrmizycxnm33eyny', 'PHID-TASK-z5f2oqlveyptphmuzqiq', 'PHID-TASK-i47cfhnm5gmi6zgg377c'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [12] <query> 2 us
>>> [13] <connect> phabricator_project
<<< [13] <connect> 674 us
>>> [14] <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-nawuhim336xjhyb5ccm7'))  ORDER BY `p`.`name` ASC
<<< [14] <query> 1 us
>>> [15] <connect> phabricator_file
<<< [15] <connect> 697 us
>>> [16] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('')) ORDER BY `f`.`id` DESC
<<< [16] <query> 360 us
>>> [17] <query> SELECT f.* FROM `file` f JOIN `file_transformedfile` t ON t.transformedPHID = f.phid WHERE (((t.originalPHID = 'PHID-VOID-00000000000000000000' AND t.transform = 'builtin:project.png'))) ORDER BY `f`.`id` DESC
<<< [17] <query> 405 us
>>> [18] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-vr6jvlxjfuh2ojmxkqs3')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [18] <query> 396 us
>>> [19] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-vr6jvlxjfuh2ojmxkqs3')
<<< [19] <query> 325 us
>>> [20] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-pxcyucr5e3lh3fqfjrpw'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [20] <query> 416 us
>>> [21] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-pxcyucr5e3lh3fqfjrpw')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [21] <query> 734 us
>>> [22] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [22] <query> 376 us
>>> [23] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-pxcyucr5e3lh3fqfjrpw')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [23] <query> 712 us
>>> [24] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-pxcyucr5e3lh3fqfjrpw'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [24] <query> 432 us
>>> [25] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-pxcyucr5e3lh3fqfjrpw/
<<< [25] <http> 10 us
>>> [26] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-pxcyucr5e3lh3fqfjrpw'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [26] <query> 396 us
>>> [27] <event> search.didUpdateIndex <listeners = 2>
<<< [27] <event> 264 us
>>> [28] <query> START TRANSACTION
<<< [28] <query> 325 us
>>> [29] <query> DELETE FROM `worker_activetask` WHERE id = 363064
<<< [29] <query> 461 us
>>> [30] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('133337', '0', 'PhabricatorSearchWorker', '5273:1432560959:ubuntu3:1', '1432568159', '0', '363061', '4000', NULL, '363064', '1432560960', '1432560960')
<<< [30] <query> 2 us
>>> [31] <query> COMMIT
<<< [31] <query> 5 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363064 complete! Moved to archive.
>>> [32] <connect> phabricator_worker
<<< [32] <connect> 628 us
>>> [33] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [33] <query> 591 us
>>> [34] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '5273:1432560960:ubuntu3:2', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363066))
<<< [34] <query> 4 us
>>> [35] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '5273:1432560960:ubuntu3:2' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [35] <query> 668 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363066 (PhabricatorSearchWorker)...
>>> [36] <connect> phabricator_maniphest
<<< [36] <connect> 647 us
>>> [37] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-y7knwqu4ixnilrwgbitv'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [37] <query> 692 us
>>> [38] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-y7knwqu4ixnilrwgbitv')) ORDER BY `id` DESC
<<< [38] <query> 1 us
>>> [39] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-y7knwqu4ixnilrwgbitv'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [39] <query> 427 us
>>> [40] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-3qbglaklbaogfgxeqzcx', 'PHID-TASK-pxcyucr5e3lh3fqfjrpw'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [40] <query> 926 us
>>> [41] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-y7knwqu4ixnilrwgbitv'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [41] <query> 443 us
>>> [42] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-y7knwqu4ixnilrwgbitv')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [42] <query> 732 us
>>> [43] <connect> phabricator_user
<<< [43] <connect> 630 us
>>> [44] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [44] <query> 334 us
>>> [45] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-y7knwqu4ixnilrwgbitv')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [45] <query> 697 us
>>> [46] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-y7knwqu4ixnilrwgbitv'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [46] <query> 406 us
>>> [47] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-y7knwqu4ixnilrwgbitv/
<<< [47] <http> 3 us
>>> [48] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-y7knwqu4ixnilrwgbitv'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [48] <query> 401 us
>>> [49] <event> search.didUpdateIndex <listeners = 2>
<<< [49] <event> 286 us
>>> [50] <query> START TRANSACTION
<<< [50] <query> 294 us
>>> [51] <query> DELETE FROM `worker_activetask` WHERE id = 363066
<<< [51] <query> 480 us
>>> [52] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('47389', '0', 'PhabricatorSearchWorker', '5273:1432560960:ubuntu3:2', '1432568160', '0', '363063', '4000', NULL, '363066', '1432560960', '1432560960')
<<< [52] <query> 511 us
>>> [53] <query> COMMIT
<<< [53] <query> 5 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363066 complete! Moved to archive.
>>> [54] <connect> phabricator_worker
<<< [54] <connect> 602 us
>>> [55] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [55] <query> 621 us
>>> [56] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '5273:1432560960:ubuntu3:3', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363069))
<<< [56] <query> 4 us
>>> [57] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '5273:1432560960:ubuntu3:3' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [57] <query> 699 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363069 (PhabricatorSearchWorker)...
>>> [58] <connect> phabricator_maniphest
<<< [58] <connect> 751 us
>>> [59] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [59] <query> 696 us
>>> [60] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-dk63tplbv7nosaijclre')) ORDER BY `id` DESC
<<< [60] <query> 1 us
>>> [61] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [61] <query> 380 us
>>> [62] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-mywytpuz5nsl2of456yn', 'PHID-TASK-c4i6pxhpd2ucmzjg3k3k', 'PHID-TASK-lmxpviviapboafutwxbu'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [62] <query> 2 us
>>> [63] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [63] <query> 395 us
>>> [64] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-dk63tplbv7nosaijclre')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [64] <query> 709 us
>>> [65] <connect> phabricator_user
<<< [65] <connect> 613 us
>>> [66] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [66] <query> 365 us
>>> [67] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-dk63tplbv7nosaijclre')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [67] <query> 685 us
>>> [68] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [68] <query> 396 us
>>> [69] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-dk63tplbv7nosaijclre/
<<< [69] <http> 2 us
>>> [70] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [70] <query> 413 us
>>> [71] <event> search.didUpdateIndex <listeners = 2>
<<< [71] <event> 285 us
>>> [72] <query> START TRANSACTION
<<< [72] <query> 308 us
>>> [73] <query> DELETE FROM `worker_activetask` WHERE id = 363069
<<< [73] <query> 484 us
>>> [74] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('48346', '0', 'PhabricatorSearchWorker', '5273:1432560960:ubuntu3:3', '1432568160', '0', '363066', '4000', NULL, '363069', '1432560960', '1432560960')
<<< [74] <query> 494 us
>>> [75] <query> COMMIT
<<< [75] <query> 4 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363069 complete! Moved to archive.
>>> [76] <connect> phabricator_worker
<<< [76] <connect> 597 us
>>> [77] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [77] <query> 838 us
>>> [78] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '5273:1432560960:ubuntu3:4', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363072))
<<< [78] <query> 4 us
>>> [79] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '5273:1432560960:ubuntu3:4' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [79] <query> 674 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363072 (PhabricatorSearchWorker)...
>>> [80] <connect> phabricator_maniphest
<<< [80] <connect> 627 us
>>> [81] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [81] <query> 390 us
>>> [82] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-dk63tplbv7nosaijclre')) ORDER BY `id` DESC
<<< [82] <query> 381 us
>>> [83] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [83] <query> 421 us
>>> [84] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [84] <query> 407 us
>>> [85] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-dk63tplbv7nosaijclre')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [85] <query> 376 us
>>> [86] <connect> phabricator_user
<<< [86] <connect> 640 us
>>> [87] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [87] <query> 469 us
>>> [88] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-dk63tplbv7nosaijclre')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [88] <query> 317 us
>>> [89] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [89] <query> 375 us
>>> [90] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-dk63tplbv7nosaijclre/
<<< [90] <http> 2 us
>>> [91] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-dk63tplbv7nosaijclre'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [91] <query> 393 us
>>> [92] <event> search.didUpdateIndex <listeners = 2>
<<< [92] <event> 258 us
>>> [93] <query> START TRANSACTION
<<< [93] <query> 268 us
>>> [94] <query> DELETE FROM `worker_activetask` WHERE id = 363072
<<< [94] <query> 446 us
>>> [95] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('42766', '0', 'PhabricatorSearchWorker', '5273:1432560960:ubuntu3:4', '1432568160', '0', '363069', '4000', NULL, '363072', '1432560960', '1432560960')
<<< [95] <query> 479 us
>>> [96] <query> COMMIT
<<< [96] <query> 11 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363072 complete! Moved to archive.
>>> [97] <connect> phabricator_worker
<<< [97] <connect> 452 us
>>> [98] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [98] <query> 509 us
>>> [99] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '5273:1432560960:ubuntu3:5', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363074))
<<< [99] <query> 4 us
>>> [100] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '5273:1432560960:ubuntu3:5' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [100] <query> 571 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363074 (PhabricatorSearchWorker)...
>>> [101] <connect> phabricator_maniphest
<<< [101] <connect> 3 us
>>> [102] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-z5f2oqlveyptphmuzqiq'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [102] <query> 580 us
>>> [103] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-z5f2oqlveyptphmuzqiq')) ORDER BY `id` DESC
>>> [8] <event> daemon.didLogMessage <listeners = 2>
>>> [9] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('235', 'STDE', '>>> [0] <connect> phabricator_config\n<<< [0] <connect> 2 us\n>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = \'default\' AND isDeleted = 0 \n<<< [1] <query> 299 us\n>>> [2] <connect> phabricator_worker\n<<< [2] <connect> 725 us\n>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1\n<<< [3] <query> 6 us\n>>> [4] <query> UPDAT
<<< [9] <query> 11 us
<<< [8] <event> 13 us
2015-05-25 1:36:43 PM [STDE] <<< [103] <query> 42 us
>>> [10] <event> daemon.didLogMessage <listeners = 2>
>>> [11] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('235', 'STDE', '<<< [103] <query> 42 us', '1432561003')
<<< [11] <query> 7 us
<<< [10] <event> 8 us
>>> [12] <event> daemon.didHeartbeat <listeners = 2>
>>> [13] <query> UPDATE `daemon_log` SET `daemon` = 'PhabricatorTaskmasterDaemon', `host` = 'ubuntu3', `pid` = '5260', `daemonID` = '5260:venpmdk', `runningAsUser` = 'root', `argv` = '[\"--trace\",\"--verbose\"]', `explicitArgv` = '[]', `envHash` = '7b83329e6bd120fbb001965e15e69d591c7deae1', `envInfo` = '{\"version\":1,\"keys\":\"MJOmom.6GshL\",\"values\":{\"darkconsole.enabled\":\"v.jX3f8wOz8F\",\"metamta.default-address\":\"d5lCyWmwd0Hc\",\"metamta.domain\":\"EQE.ursbVGC_\",\"metamta.mail-adapter\":\"fuAsxCdTSGpp\",\"mysq
<<< [13] <query> 27 us
<<< [12] <event> 127 us
>>> [14] <event> daemon.didHeartbeat <listeners = 2>
>>> [15] <query> UPDATE `daemon_log` SET `daemon` = 'PhabricatorTaskmasterDaemon', `host` = 'ubuntu3', `pid` = '5260', `daemonID` = '5260:venpmdk', `runningAsUser` = 'root', `argv` = '[\"--trace\",\"--verbose\"]', `explicitArgv` = '[]', `envHash` = '7b83329e6bd120fbb001965e15e69d591c7deae1', `envInfo` = '{\"version\":1,\"keys\":\"MJOmom.6GshL\",\"values\":{\"darkconsole.enabled\":\"v.jX3f8wOz8F\",\"metamta.default-address\":\"d5lCyWmwd0Hc\",\"metamta.domain\":\"EQE.ursbVGC_\",\"metamta.mail-adapter\":\"fuAsxCdTSGpp\",\"mysq
<<< [15] <query> 17 us
<<< [14] <event> 38 us

There is around a 2 minute pause between printouts
date
Mon May 25 21:38:12 HKT 2015
date
Mon May 25 21:40:01 HKT 2015

epriestley added a comment.May 25 2015, 1:44 PM

Can you update libphutil and retry that? The duration printouts are bugged until rPHU65819efa.

Does bin/storage adjust report missing keys?

JoggerTech added a comment.May 25 2015, 1:50 PM

git pull

remote: Counting objects: 19, done.
remote: Compressing objects: 100% (19/19), done.
remote: Total 19 (delta 15), reused 4 (delta 0), pack-reused 0
Unpacking objects: 100% (19/19), done.
From git://github.com/facebook/libphutil
   4e0febf..672c0f7  master     -> origin/master
Updating 4e0febf..672c0f7
Fast-forward
 .arcconfig                                    | 1 -
 src/daemon/PhutilDaemon.php                   | 5 +++--
 src/daemon/PhutilDaemonHandle.php             | 7 +++++--
 src/future/exec/CommandException.php          | 2 +-
 src/moduleutils/PhutilLibraryMapBuilder.php   | 4 ++--
 src/serviceprofiler/PhutilServiceProfiler.php | 4 ++--
 6 files changed, 13 insertions(+), 10 deletions(-)

git log

commit 672c0f7d5da9be6cda619428a9da3b91a670ea2f
Date:   Mon May 25 22:42:15 2015 +1000

bin/storage adjust

Verifying database schemata...
Found no adjustments for schemata.

before phd

KiB Mem:  16120708 total,  2691624 used, 13429084 free,    34236 buffers
KiB Swap: 16457724 total,  1425900 used, 15031824 free.   860072 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1528 elastic+  20   0 3552148 255760   4848 S   8.3  1.6  20:00.75 java
24415 mysql     20   0 2556016 972056   2376 S   3.0  6.0  56:00.27 mysqld

bin/phd debug taskmaster

Launching daemons (in debug mode):
(Logs will appear in "/var/tmp/phd/log/daemons.log".)

    PhabricatorTaskmasterDaemon (Static)


    phabricator/scripts/daemon/ $ ./phd-daemon '--trace' '--verbose'

>>> [2] <event> daemon.didLaunch <listeners = 2>
>>> [3] <connect> phabricator_daemon
<<< [3] <connect> 472 us
>>> [4] <query> INSERT INTO `daemon_log` (`daemon`, `host`, `pid`, `daemonID`, `runningAsUser`, `argv`, `explicitArgv`, `envHash`, `envInfo`, `status`, `dateCreated`, `dateModified`) VALUES ('PhabricatorTaskmasterDaemon', 'ubuntu3', '28250', '28250:h6lwah', 'root', '[\"--trace\",\"--verbose\"]', '[]', '7b83329e6bd120fbb001965e15e69d591c7deae1', '{\"version\":1,\"keys\":\"MJOmom.6GshL\",\"values\":{\"darkconsole.enabled\":\"v.jX3f8wOz8F\",\"metamta.default-address\":\"d5lCyWmwd0Hc\",\"metamta.domain\":\"EQE.ursbVGC_\",\"met
<<< [4] <query> 10,775 us
<<< [2] <event> 27,626 us
2015-05-25 1:47:14 PM [INIT] Starting process.
>>> [5] <event> daemon.didLogMessage <listeners = 2>
>>> [6] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('236', 'INIT', 'Starting process.', '1432561634')
<<< [6] <query> 4,719 us
<<< [5] <event> 5,778 us
>>> [7] <exec> $ exec ./exec_daemon.php 'PhabricatorTaskmasterDaemon' '--trace' '--verbose'
2015-05-25 1:47:15 PM [STDE] >>> [0] <connect> phabricator_config
<<< [0] <connect> 2,697 us
>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = 'default' AND isDeleted = 0
<<< [1] <query> 284 us
>>> [2] <connect> phabricator_worker
<<< [2] <connect> 612 us
>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [3] <query> 577 us
>>> [4] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '28254:1432561634:ubuntu3:1', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363086))
<<< [4] <query> 5,748 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 task.leaseOwner = '28254:1432561634:ubuntu3:1' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [5] <query> 5,047 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363086 (PhabricatorSearchWorker)...
>>> [6] <connect> phabricator_maniphest
<<< [6] <connect> 591 us
>>> [7] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-2xrg5tqyoovm7ykcdo22'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [7] <query> 622 us
>>> [8] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-2xrg5tqyoovm7ykcdo22')) ORDER BY `id` DESC
<<< [8] <query> 2,165 us
>>> [9] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-2xrg5tqyoovm7ykcdo22'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [9] <query> 371 us
>>> [10] <connect> phabricator_user
<<< [10] <connect> 643 us
>>> [11] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [11] <query> 304 us
>>> [12] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-blg3wf5hsrtybv5jxho5', 'PHID-TASK-og23f34vgz5dlkd5mxwz', 'PHID-TASK-z5f2oqlveyptphmuzqiq', 'PHID-TASK-6d7n5mnk3vlllm45eann', 'PHID-TASK-73xny7sqty67gvn4zbtj', 'PHID-TASK-i47cfhnm5gmi6zgg377c'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [12] <query> 3,582 us
>>> [13] <connect> phabricator_project
<<< [13] <connect> 630 us
>>> [14] <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-nawuhim336xjhyb5ccm7'))  ORDER BY `p`.`name` ASC
<<< [14] <query> 1,139 us
>>> [15] <connect> phabricator_file
<<< [15] <connect> 649 us
>>> [16] <query> SELECT f.* FROM `file` f  WHERE (f.phid IN ('')) ORDER BY `f`.`id` DESC
<<< [16] <query> 313 us
>>> [17] <query> SELECT f.* FROM `file` f JOIN `file_transformedfile` t ON t.transformedPHID = f.phid WHERE (((t.originalPHID = 'PHID-VOID-00000000000000000000' AND t.transform = 'builtin:project.png'))) ORDER BY `f`.`id` DESC
<<< [17] <query> 358 us
>>> [18] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-FILE-vr6jvlxjfuh2ojmxkqs3')) AND (edge.type IN ('26')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [18] <query> 344 us
>>> [19] <query> SELECT * FROM `file_transformedfile` WHERE transformedPHID IN ('PHID-FILE-vr6jvlxjfuh2ojmxkqs3')
<<< [19] <query> 262 us
>>> [20] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-2xrg5tqyoovm7ykcdo22'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [20] <query> 382 us
>>> [21] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-2xrg5tqyoovm7ykcdo22')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [21] <query> 1,775 us
>>> [22] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [22] <query> 337 us
>>> [23] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-2xrg5tqyoovm7ykcdo22')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [23] <query> 699 us
>>> [24] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-2xrg5tqyoovm7ykcdo22'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [24] <query> 374 us
>>> [25] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-2xrg5tqyoovm7ykcdo22/
<<< [25] <http> 15,957 us
>>> [26] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-2xrg5tqyoovm7ykcdo22'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [26] <query> 369 us
>>> [27] <event> search.didUpdateIndex <listeners = 2>
<<< [27] <event> 260 us
>>> [28] <query> START TRANSACTION
<<< [28] <query> 326 us
>>> [29] <query> DELETE FROM `worker_activetask` WHERE id = 363086
<<< [29] <query> 452 us
>>> [30] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('139161', '0', 'PhabricatorSearchWorker', '28254:1432561634:ubuntu3:1', '1432568834', '0', '363083', '4000', NULL, '363086', '1432561634', '1432561634')
<<< [30] <query> 475 us
>>> [31] <query> COMMIT
<<< [31] <query> 4,989 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363086 complete! Moved to archive.
>>> [32] <connect> phabricator_worker
<<< [32] <connect> 584 us
>>> [33] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [33] <query> 545 us
>>> [34] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '28254:1432561634:ubuntu3:2', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363088))
<<< [34] <query> 10,925 us
>>> [35] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '28254:1432561634:ubuntu3:2' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [35] <query> 688 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363088 (PhabricatorSearchWorker)...
>>> [36] <connect> phabricator_maniphest
<<< [36] <connect> 442 us
>>> [37] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-blg3wf5hsrtybv5jxho5'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [37] <query> 671 us
>>> [38] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-blg3wf5hsrtybv5jxho5')) ORDER BY `id` DESC
<<< [38] <query> 781 us
>>> [39] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-blg3wf5hsrtybv5jxho5'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [39] <query> 382 us
>>> [40] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-nnunne3jaotijhkvfszp', 'PHID-TASK-wyb2kdzxlnblveq4jfs5', 'PHID-TASK-2xrg5tqyoovm7ykcdo22'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [40] <query> 1,150 us
>>> [41] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-blg3wf5hsrtybv5jxho5'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [41] <query> 345 us
>>> [42] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-blg3wf5hsrtybv5jxho5')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [42] <query> 698 us
>>> [43] <connect> phabricator_user
<<< [43] <connect> 551 us
>>> [44] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [44] <query> 293 us
>>> [45] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-blg3wf5hsrtybv5jxho5')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [45] <query> 643 us
>>> [46] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-blg3wf5hsrtybv5jxho5'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [46] <query> 334 us
>>> [47] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-blg3wf5hsrtybv5jxho5/
<<< [47] <http> 2,273 us
>>> [48] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-blg3wf5hsrtybv5jxho5'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [48] <query> 351 us
>>> [49] <event> search.didUpdateIndex <listeners = 2>
<<< [49] <event> 254 us
>>> [50] <query> START TRANSACTION
<<< [50] <query> 272 us
>>> [51] <query> DELETE FROM `worker_activetask` WHERE id = 363088
<<< [51] <query> 401 us
>>> [52] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('40683', '0', 'PhabricatorSearchWorker', '28254:1432561634:ubuntu3:2', '1432568834', '0', '363085', '4000', NULL, '363088', '1432561634', '1432561634')
<<< [52] <query> 431 us
>>> [53] <query> COMMIT
<<< [53] <query> 10,970 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363088 complete! Moved to archive.
>>> [54] <connect> phabricator_worker
<<< [54] <connect> 609 us
>>> [55] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [55] <query> 527 us
>>> [56] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '28254:1432561634:ubuntu3:3', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363091))
<<< [56] <query> 10,552 us
>>> [57] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '28254:1432561634:ubuntu3:3' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [57] <query> 596 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363091 (PhabricatorSearchWorker)...
>>> [58] <connect> phabricator_maniphest
<<< [58] <connect> 521 us
>>> [59] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [59] <query> 650 us
>>> [60] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-fytzgncfqa7gcuofrj3j')) ORDER BY `id` DESC
<<< [60] <query> 10,792 us
>>> [61] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [61] <query> 210 us
>>> [62] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-m6eevemxhcmtsvwdu43u', 'PHID-TASK-ovxyv4xm6ak5575k2qez', 'PHID-TASK-4rybohp4ksxvk3cpv4fy'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [62] <query> 2,142 us
>>> [63] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [63] <query> 231 us
>>> [64] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-fytzgncfqa7gcuofrj3j')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [64] <query> 910 us
>>> [65] <connect> phabricator_user
<<< [65] <connect> 416 us
>>> [66] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [66] <query> 262 us
>>> [67] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-fytzgncfqa7gcuofrj3j')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [67] <query> 493 us
>>> [68] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [68] <query> 216 us
>>> [69] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-fytzgncfqa7gcuofrj3j/
<<< [69] <http> 1,899 us
>>> [70] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [70] <query> 220 us
>>> [71] <event> search.didUpdateIndex <listeners = 2>
<<< [71] <event> 130 us
>>> [72] <query> START TRANSACTION
<<< [72] <query> 157 us
>>> [73] <query> DELETE FROM `worker_activetask` WHERE id = 363091
<<< [73] <query> 328 us
>>> [74] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('51892', '0', 'PhabricatorSearchWorker', '28254:1432561634:ubuntu3:3', '1432568834', '0', '363088', '4000', NULL, '363091', '1432561634', '1432561634')
<<< [74] <query> 351 us
>>> [75] <query> COMMIT
<<< [75] <query> 17,066 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363091 complete! Moved to archive.
>>> [76] <connect> phabricator_worker
<<< [76] <connect> 443 us
>>> [77] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [77] <query> 415 us
>>> [78] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '28254:1432561634:ubuntu3:4', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363094))
<<< [78] <query> 4,435 us
>>> [79] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '28254:1432561634:ubuntu3:4' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [79] <query> 567 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363094 (PhabricatorSearchWorker)...
>>> [80] <connect> phabricator_maniphest
<<< [80] <connect> 440 us
>>> [81] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [81] <query> 311 us
>>> [82] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-fytzgncfqa7gcuofrj3j')) ORDER BY `id` DESC
<<< [82] <query> 280 us
>>> [83] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [83] <query> 333 us
>>> [84] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [84] <query> 324 us
>>> [85] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-fytzgncfqa7gcuofrj3j')) AND (edge.type IN ('21')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [85] <query> 273 us
>>> [86] <connect> phabricator_user
<<< [86] <connect> 457 us
>>> [87] <query> SELECT * FROM `user` user  WHERE (user.phid IN ('PHID-USER-62bffrfjqshlaqqjt5p4'))  ORDER BY `user`.`id` DESC
<<< [87] <query> 167 us
>>> [88] <query> SELECT edge.* FROM `edge` edge WHERE (edge.src IN ('PHID-TASK-fytzgncfqa7gcuofrj3j')) AND (edge.type IN ('41')) ORDER BY edge.dateCreated DESC, edge.seq DESC
<<< [88] <query> 280 us
>>> [89] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [89] <query> 318 us
>>> [90] <http> http://localhost:9200/phabricator/TASK/PHID-TASK-fytzgncfqa7gcuofrj3j/
<<< [90] <http> 1,513 us
>>> [91] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-fytzgncfqa7gcuofrj3j'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [91] <query> 339 us
>>> [92] <event> search.didUpdateIndex <listeners = 2>
<<< [92] <event> 128 us
>>> [93] <query> START TRANSACTION
<<< [93] <query> 156 us
>>> [94] <query> DELETE FROM `worker_activetask` WHERE id = 363094
<<< [94] <query> 325 us
>>> [95] <query> INSERT INTO `worker_archivetask` (`duration`, `result`, `taskClass`, `leaseOwner`, `leaseExpires`, `failureCount`, `dataID`, `priority`, `objectPHID`, `id`, `dateCreated`, `dateModified`) VALUES ('31315', '0', 'PhabricatorSearchWorker', '28254:1432561634:ubuntu3:4', '1432568834', '0', '363091', '4000', NULL, '363094', '1432561634', '1432561634')
<<< [95] <query> 351 us
>>> [96] <query> COMMIT
<<< [96] <query> 3,959 us
<<VERB>> PhabricatorTaskmasterDaemon Task 363094 complete! Moved to archive.
>>> [97] <connect> phabricator_worker
<<< [97] <connect> 436 us
>>> [98] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1
<<< [98] <query> 437 us
>>> [99] <query> UPDATE `worker_activetask` task
              SET leaseOwner = '28254:1432561634:ubuntu3:5', leaseExpires = UNIX_TIMESTAMP() + 7200
              WHERE (leaseOwner IS NULL) AND (id IN (363096))
<<< [99] <query> 4,734 us
>>> [100] <query> SELECT task.*, taskdata.data _taskData, UNIX_TIMESTAMP() _serverTime
        FROM `worker_activetask` task LEFT JOIN `worker_taskdata` taskdata
          ON taskdata.id = task.dataID
        WHERE task.leaseOwner = '28254:1432561634:ubuntu3:5' AND leaseExpires > UNIX_TIMESTAMP() ORDER BY priority ASC, id ASC LIMIT 1
<<< [100] <query> 507 us
<<VERB>> PhabricatorTaskmasterDaemon Working on task 363096 (PhabricatorSearchWorker)...
>>> [101] <connect> phabricator_maniphest
<<< [101] <connect> 438 us
>>> [102] <query> SELECT `task`.*  FROM `maniphest_task` task  WHERE (task.phid in ('PHID-TASK-z5f2oqlveyptphmuzqiq'))   ORDER BY `task`.`dateModified` DESC, `task`.`id` DESC
<<< [102] <query> 463 us
>>> [103] <query> SELECT * FROM `maniphest_transaction` x WHERE (objectPHID IN ('PHID-TASK-z5f2oqlveyptphmuzqiq')) ORDER BY `id` DESC
>>> [8] <event> daemon.didLogMessage <listeners = 2>
>>> [9] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('236', 'STDE', '>>> [0] <connect> phabricator_config\n<<< [0] <connect> 2,697 us\n>>> [1] <query> SELECT * FROM `config_entry` WHERE namespace = \'default\' AND isDeleted = 0 \n<<< [1] <query> 284 us\n>>> [2] <connect> phabricator_worker\n<<< [2] <connect> 612 us\n>>> [3] <query> SELECT id, leaseOwner FROM `worker_activetask` WHERE (leaseOwner IS NULL) ORDER BY priority ASC, id ASC LIMIT 1\n<<< [3] <query> 577 us\n>>> [4] <query>
<<< [9] <query> 8,414 us
<<< [8] <event> 10,677 us
2015-05-25 1:47:47 PM [STDE] <<< [103] <query> 32,207,332 us
>>> [10] <event> daemon.didLogMessage <listeners = 2>
>>> [11] <query> INSERT INTO `daemon_logevent` (`logID`, `logType`, `message`, `epoch`) VALUES ('236', 'STDE', '<<< [103] <query> 32,207,332 us', '1432561667')
<<< [11] <query> 5,751 us
<<< [10] <event> 6,539 us

phd loaded

KiB Mem:  16120708 total, 15948868 used,   171840 free,    10804 buffers
KiB Swap: 16457724 total,  1064980 used, 15392744 free.   236720 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
28254 root      20   0 13.308g 0.013t   8320 R  98.9 85.0   1:05.82 php
31752 root      20   0  286176  35024   8296 S  10.0  0.2   0:00.30 php
24415 mysql     20   0 2556016 1.265g   2380 S   3.0  8.2  56:23.31 mysqld

Any thought on the jump in Mem used for 1 instance and cpu of 98.9%

epriestley added a comment.May 25 2015, 1:54 PM

Where are the two-second delays occurring? Everything in that trace looks like it happens in no more than a few milliseconds.

It's expected that daemons with a nonempty queue will be primarily CPU-bound in many cases.

I have no clue on the memory usage. We have less sophisticated tools for examining memory usage that runtime performance (and PHP itself also has less sophisticated tools); see some discussion in T3848. What tooling we do have is focused on finding leaks, not assessing allocations.

JoggerTech added a comment.May 25 2015, 1:59 PM

2 minute delays between prints.
Maybe an incorrect assessment, but I see there is a direct relationship to the my.conf vs how much mem/swap is used once I start phd; but always max CPU and obviously this impacts severely apache browsing and conduit api response

my.conf

innodb_buffer_pool_size=1600M
max_allowed_packet = 32M
chad added a subscriber: chad.May 25 2015, 4:01 PM

I don't know if it's worth noting, but Ubuntu 10.04 was end of life'd last month (it's 5 years old). What versions of PHP/MySQL are you running on it?

JoggerTech added a comment.May 28 2015, 3:10 AM
php -v
PHP 5.5.9-1ubuntu4.7 (cli) (built: Mar 16 2015 20:47:39)
Copyright (c) 1997-2014 The PHP Group
Zend Engine v2.5.0, Copyright (c) 1998-2014 Zend Technologies
    with Zend OPcache v7.0.3, Copyright (c) 1999-2014, by Zend Technologies
 mysql -v
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1830330
Server version: 5.5.41-0ubuntu0.14.04.1 (Ubuntu)
JoggerTech added a comment.EditedMay 28 2015, 3:11 AM

Can you tell me the configuration setup that you guys are using:
OS, core#, memory (size, speed), SSD, php, mysql?

chad mentioned this in T8380: Queueing search indexers is very slow.Jun 2 2015, 1:59 AM
epriestley closed this task as Invalid.Jan 15 2016, 1:36 PM
epriestley claimed this task.

Just closing this since it's a huge fishing expedition that we can't help with, see Contributing Bug Reports and Support Resources.

Phabricator · Built by Phacility