Page MenuHomePhabricator

Forking in hhvm emits notices from RedisConnectionPool::__destruct() when the process ends due to holding on to sockets that don't exist in that process.
Closed, DeclinedPublic

Description

1vagrant@mediawiki-vagrant:/vagrant/mediawiki/extensions/CirrusSearch/maintenance$ php updateSearchIndexConfig.php --reindexAndRemoveOk --indexIdentifier now
2content index...
3 Fetching Elasticsearch version...1.3.7...ok
4 Scanning available plugins...
5 experimental highlighter, analysis-stempel, analysis-smartcn, analysis-kuromoji, analysis-icu
6 wikimedia-extra
7 Setting index identifier...wiki_content_1420689524
8 Picking analyzer...english
9 Creating index...ok
10 Validating analyzers...ok
11 Validating mappings...
12 Validating mapping...different...corrected
13 Validating cache warmers...
14 Updating Main Page...done
15 Validating aliases...
16 Validating content alias...is taken...
17 Reindexing...
18 [0] Starting child process reindex
19 [1] Starting child process reindex
20 [2] Starting child process reindex
21 [3] Starting child process reindex
22 [4] Starting child process reindex
23 [1] About to reindex 996 documents
24 [0] About to reindex 1015 documents
25 [2] About to reindex 1043 documents
26 [4] About to reindex 1004 documents
27 [3] About to reindex 1010 documents
28 [2] Reindexed 400/1043 documents at 28/second
29 [4] Reindexed 400/1004 documents at 22/second
30 [1] Reindexed 400/996 documents at 20/second
31 [0] Reindexed 400/1015 documents at 19/second
32 [3] Reindexed 400/1010 documents at 17/second
33 [2] Reindexed 787/1043 documents at 31/second
34 [4] Reindexed 754/1004 documents at 29/second
35 [1] Reindexed 757/996 documents at 27/second
36 [0] Reindexed 770/1015 documents at 26/second
37 [3] Reindexed 764/1010 documents at 25/second
38 [4] Reindexed 948/1004 documents at 30/second
39 [2] Reindexed 1001/1043 documents at 32/second
40 [1] Reindexed 957/996 documents at 29/second
41 [0] Reindexed 965/1015 documents at 29/second
42 [3] Reindexed 960/1010 documents at 29/second
43 [4] Reindexed 1004/1004 documents at 30/second
44 [4] All done
45 [2] Reindexed 1043/1043 documents at 31/second
46 [2] All done
47 [1] Reindexed 996/996 documents at 29/second
48 [1] All done
49[Thu Jan 8 03:59:25 2015] [hphp] [4184:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
50Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
51 [3] Reindexed 1010/1010 documents at 30/second
52 [3] All done
53[Thu Jan 8 03:59:25 2015] [hphp] [4186:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
54Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
55 [0] Reindexed 1015/1015 documents at 30/second
56 [0] All done
57[Thu Jan 8 03:59:25 2015] [hphp] [4183:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
58Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
59 Verifying counts...done
60 Optimizing...Done
61 Validating number of shards...ok
62 Validating replica range...ok
63 Validating shard allocation settings...done
64 Validating max shards per node...is 12 but should be unlimited...corrected
65 Waiting for all shards to start...
66 active:4/4 relocating:0 initializing:0 unassigned:0
67 Swapping alias...done
68 Validating wiki alias...alias not already assigned to this index...corrected
69 Removing old indices...
70 wiki_content_1420486190...done
71 Validating number of shards...ok
72 Validating replica range...ok
73 Validating shard allocation settings...done
74 Validating max shards per node...ok
75 Removing old indecies...
76 wiki_content_1420480707...done
77 Updating tracking indexes...done
78general index...
79 Fetching Elasticsearch version...1.3.7...ok
80 Scanning available plugins...
81 experimental highlighter, analysis-stempel, analysis-smartcn, analysis-kuromoji, analysis-icu
82 wikimedia-extra
83 Setting index identifier...wiki_general_1420689567
84 Picking analyzer...english
85 Creating index...ok
86 Validating analyzers...ok
87 Validating mappings...
88 Validating mapping...different...corrected
89 Validating cache warmers...
90 Validating aliases...
91 Validating general alias...is taken...
92 Reindexing...
93 [0] Starting child process reindex
94 [1] Starting child process reindex
95 [2] Starting child process reindex
96 [3] Starting child process reindex
97 [4] Starting child process reindex
98 [0] About to reindex 333 documents
99 [2] About to reindex 305 documents
100 [1] About to reindex 350 documents
101 [3] About to reindex 341 documents
102 [4] About to reindex 344 documents
103 [2] Reindexed 303/305 documents at 103/second
104 [0] Reindexed 318/333 documents at 95/second
105 [1] Reindexed 332/350 documents at 83/second
106 [3] Reindexed 320/341 documents at 68/second
107 [2] Reindexed 305/305 documents at 60/second
108 [2] All done
109[Thu Jan 8 03:59:33 2015] [hphp] [4205:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
110Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
111 [0] Reindexed 333/333 documents at 65/second
112 [0] All done
113[Thu Jan 8 03:59:33 2015] [hphp] [4203:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
114Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
115 [1] Reindexed 350/350 documents at 68/second
116 [1] All done
117[Thu Jan 8 03:59:33 2015] [hphp] [4204:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
118Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
119 [3] Reindexed 341/341 documents at 65/second
120 [3] All done
121[Thu Jan 8 03:59:33 2015] [hphp] [4206:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
122Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
123 [4] Reindexed 329/344 documents at 62/second
124 [4] Reindexed 344/344 documents at 64/second
125 [4] All done
126[Thu Jan 8 03:59:33 2015] [hphp] [4207:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
127Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe
128 Verifying counts...done
129 Optimizing...Done
130 Validating number of shards...ok
131 Validating replica range...ok
132 Validating shard allocation settings...done
133 Validating max shards per node...is 12 but should be unlimited...corrected
134 Waiting for all shards to start...
135 active:4/4 relocating:0 initializing:0 unassigned:0
136 Swapping alias...done
137 Validating wiki alias...alias not already assigned to this index...corrected
138 Validating number of shards...ok
139 Validating replica range...ok
140 Validating shard allocation settings...done
141 Validating max shards per node...ok
142 Removing old indecies...
143 wiki_general_1420480708...done
144 Updating tracking indexes...done
145 Deleting namespaces...done
146 Indexing namespaces...done
147[Thu Jan 8 03:59:35 2015] [hphp] [4173:7f3488e27c00:0:000001] [95da1a:efbb58:14f9cf1:c6a1d1:c4c13e:c4dd80:a3c3b0:c4417d:9c455c:9c6376:9ca252:9cb86f:a69581:8548fd:7f3480a4fec5:907b94]
148Notice: fwrite(): send of 14 bytes failed with errno=32 Broken pipe

Details

Related Gerrit Patches:

Related Objects

Mentioned Here
P197 fork mess

Event Timeline

demon created this task.Dec 30 2014, 10:19 PM
demon raised the priority of this task from to Needs Triage.
demon updated the task description. (Show Details)
demon added projects: CirrusSearch, HHVM.
demon added a project: MediaWiki-Core-Team.
demon set Security to None.
demon added subscribers: demon, Manybubbles.
demon updated the task description. (Show Details)Jan 8 2015, 4:03 AM
ksmith triaged this task as Low priority.Apr 2 2015, 5:51 PM
Manybubbles moved this task from Needs triage to Search on the Discovery board.May 7 2015, 7:59 PM
EBernhardson lowered the priority of this task from Low to Lowest.May 13 2015, 8:12 PM

This doesn't actually fail, the notices are just from RedisConnectionPool::__destruct() attempting to close a connection that was opened on another fork. I toyed around with this a bit and got the reference count down from 6 to 2, but i can't figure out where that last reference is being held and it really doesn't matter, its not hurting anything yet.

EBernhardson renamed this task from Forking while reindexing fails on HHVM to Forking in hhvm emits notices from RedisConnectionPool::__destruct() when the process ends due to holding on to sockets that don't exist in that process..May 13 2015, 8:13 PM

I should also note that this doesn't appear to be due to HHVM's lack of garbage collection, these objects arn't destroyed at the right time in php5 when forcing garbage collection pre-fork either.

Oh fun. Forking is a huge pain. Maybe it makes sense to use hhvm's work api thing. I forget what it is called and don't know if it'd be better. Maybe we just ignore these.

EBernhardson added a comment.EditedMay 13 2015, 9:24 PM

hhvm has a couple different methods for that: xbox server, pagelet server, and rpc server. All of them only work when in server mode, not cli, so probably not worth the effort.

EBernhardson added a comment.EditedMay 13 2015, 9:59 PM

Actually it looks like pagelet server is available from CLI, but would have to be enabled either in the global config file, or via some extra commandline options:

hhvm -vServer.SourceRoot=$PWD -vPageletServer.ThreadCount=5 foo.php
<?php

if(empty($_GET['pagelet'])) {
        $task = pagelet_server_task_start("foo.php?pagelet=1", array(), '');
        var_dump( pagelet_server_task_result( $task, $headers, $code, 1000) );
} else {
        echo "Hello from pagelet!";
}

I could poke at this and turn it into something similar to the ForkController, but i wonder if the requirements for extra CLI options is going to make it more trouble than its worth for most installations.

seems i spoke too soon, xbox server works too :)

hhvm -vXbox.ServerInfo.RequestInitDocument=$PWD/foo.php foo.php
if(empty($_SERVER['THREAD_TYPE'])) {
        $t = xbox_task_start('1');
        xbox_task_result($t, 0, $r);
        var_dump($r);
} else {
        function xbox_process_message($msg) {
                return "In xbox: $msg";
        }
}

I'm ok with saying that multi-process reindexing is an hhvm only thing so
long as that actually makes it simpler.

Deskana removed EBernhardson as the assignee of this task.Dec 5 2015, 7:07 AM
Deskana added subscribers: EBernhardson, Deskana.

I'm guessing that @EBernhardson has not been secretly working on this for the past seven months, and unassigning.

Deskana moved this task from Needs triage to Search on the Discovery board.Dec 5 2015, 7:08 AM

Change 257059 had a related patch set uploaded (by Aaron Schulz):
Make ForkController destroy redis instances too

https://gerrit.wikimedia.org/r/257059

Change 257059 merged by jenkins-bot:
Make ForkController destroy redis instances too

https://gerrit.wikimedia.org/r/257059

demon removed a subscriber: demon.Feb 7 2017, 5:55 AM
Restricted Application added a project: Discovery-Search. · View Herald TranscriptFeb 7 2017, 5:55 AM
debt closed this task as Declined.Mar 9 2017, 11:19 PM
debt added a subscriber: debt.

This is an old ticket that just wasn't resolved with the earlier fix that was merged; plus, with the new ElasticSearch 5 update, we don't fork anymore.