Page MenuHomePhabricator

Performance issue in HHVM with output buffer?
Closed, ResolvedPublic

Description

From my cheap VPS in LA:

ab -n20 'https://en.wikipedia.org/w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama'

Server Software:        nginx/1.1.19
Server Hostname:        en.wikipedia.org
Server Port:            443
SSL/TLS Protocol:       TLSv1.2,ECDHE-RSA-AES128-GCM-SHA256,2048,128

Document Path:          /w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama
Document Length:        4095263 bytes

Concurrency Level:      1
Time taken for tests:   144.733 seconds
Complete requests:      20
Failed requests:        0
Total transferred:      81918086 bytes
HTML transferred:       81905260 bytes
Requests per second:    0.14 [#/sec] (mean)
Time per request:       7236.634 [ms] (mean)
Time per request:       7236.634 [ms] (mean, across all concurrent requests)
Transfer rate:          552.73 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       43   61  56.6     47     296
Processing:  2168 7176 7539.6   4625   34548
Waiting:     1960 4308 908.8   4367    5470
Total:       2211 7237 7572.9   4669   34642

Percentage of the requests served within a certain time (ms)
  50%   4669
  66%   5457
  75%   5549
  80%   6142
  90%  20672
  95%  34642
  98%  34642
  99%  34642
 100%  34642 (longest request)

To rule out that this is caused by https, I repeated the experiment with http:

ab -n20 'http://en.wikipedia.org/w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama'
This is ApacheBench, Version 2.3 <$Revision: 1604373 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking en.wikipedia.org (be patient).....done


Server Software:        Apache
Server Hostname:        en.wikipedia.org
Server Port:            80

Document Path:          /w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama
Document Length:        4095263 bytes

Concurrency Level:      1
Time taken for tests:   181.187 seconds
Complete requests:      20
Failed requests:        0
Total transferred:      81917216 bytes
HTML transferred:       81905260 bytes
Requests per second:    0.11 [#/sec] (mean)
Time per request:       9059.367 [ms] (mean)
Time per request:       9059.367 [ms] (mean, across all concurrent requests)
Transfer rate:          441.52 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       12  115 309.1     14    1021
Processing:  2036 8944 4865.5  10475   16402
Waiting:     1879 3277 1041.4   4077    4464
Total:       2050 9059 5002.1  10492   17419

Percentage of the requests served within a certain time (ms)
  50%  10492
  66%  11933
  75%  14249
  80%  14588
  90%  14840
  95%  17419
  98%  17419
  99%  17419
 100%  17419 (longest request)

This is on average more than four times slower than the equivalent content request directly to the parsoid caches, even after taking into account the slightly larger response body:

ab -n20 http://parsoid-lb.eqiad.wikimedia.org/enwiki/Barack_Obama?oldid=643768869
Server Software:        
Server Hostname:        parsoid-lb.eqiad.wikimedia.org
Server Port:            80

Document Path:          /enwiki/Barack_Obama?oldid=643768869
Document Length:        3592164 bytes

Concurrency Level:      1
Time taken for tests:   28.005 seconds
Complete requests:      20
Failed requests:        0
Total transferred:      71853606 bytes
HTML transferred:       71843280 bytes
Requests per second:    0.71 [#/sec] (mean)
Time per request:       1400.269 [ms] (mean)
Time per request:       1400.269 [ms] (mean, across all concurrent requests)
Transfer rate:          2505.57 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       69   70   1.4     69      73
Processing:   862 1330 319.4   1348    2092
Waiting:       88  233 321.8     95    1322
Total:        931 1400 319.6   1418    2161

Percentage of the requests served within a certain time (ms)
  50%   1418
  66%   1528
  75%   1552
  80%   1628
  90%   1867
  95%   2161
  98%   2161
  99%   2161
 100%   2161 (longest request)

All requests are Parsoid Varnish hits, as witnessed by hit/200 entries in the logs on cp1045.

Event Timeline

GWicke raised the priority of this task from to Needs Triage.
GWicke updated the task description. (Show Details)
GWicke subscribed.
GWicke set Security to None.
GWicke edited subscribers, added: Catrope, ori, BBlack; removed: Aklapper.

Interestingly, things are much snappier from tin:

ab -n20 'http://en.wikipedia.org/w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama'                                                                
This is ApacheBench, Version 2.3 <$Revision: 655654 $>                                            
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/                          
Licensed to The Apache Software Foundation, http://www.apache.org/                                
                                                                                                  
Benchmarking en.wikipedia.org (be patient).....done                                               
                                                                                                  
                                                                                                  
Server Software:        Apache                                                                    
Server Hostname:        en.wikipedia.org                                                          
Server Port:            80                                                                        
                                                                                                  
Document Path:          /w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama                                                                                       
Document Length:        4095263 bytes                                                             
                                                                                                  
Concurrency Level:      1                                                                         
Time taken for tests:   18.595 seconds                                                            
Complete requests:      20                                                                        
Failed requests:        0                                                                         
Write errors:           0                                                                         
Total transferred:      81915886 bytes                                                            
HTML transferred:       81905260 bytes                                                            
Requests per second:    1.08 [#/sec] (mean)                                                       
Time per request:       929.765 [ms] (mean)                                                       
Time per request:       929.765 [ms] (mean, across all concurrent requests)                       
Transfer rate:          4301.95 [Kbytes/sec] received                                             
                                                                                                  
Connection Times (ms)                                                                             
              min  mean[+/-sd] median   max                                                       
Connect:        0    0   0.1      0       0                                                       
Processing:   536  929 328.7    865    1658                                                       
Waiting:      500  892 329.2    828    1621                                                       
Total:        537  930 328.7    865    1659                                                       
                                                                                                  
Percentage of the requests served within a certain time (ms)                                      
  50%    865                                                                                      
  66%    903                                                                                      
  75%   1005
  80%   1274
  90%   1563
  95%   1659
  98%   1659
  99%   1659
 100%   1659 (longest request)

However, the performance delta vs. direct requests to the Parsoid Varnishes is still significant:

ab -n20 http://parsoid-lb.eqiad.wikimedia.org/enwiki/Barack_Obama?oldid=643768869
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking parsoid-lb.eqiad.wikimedia.org (be patient).....done


Server Software:        
Server Hostname:        parsoid-lb.eqiad.wikimedia.org
Server Port:            80

Document Path:          /enwiki/Barack_Obama?oldid=643768869
Document Length:        3592164 bytes

Concurrency Level:      1
Time taken for tests:   1.901 seconds
Complete requests:      20
Failed requests:        0
Write errors:           0
Total transferred:      71853720 bytes
HTML transferred:       71843280 bytes
Requests per second:    10.52 [#/sec] (mean)
Time per request:       95.071 [ms] (mean)
Time per request:       95.071 [ms] (mean, across all concurrent requests)
Transfer rate:          36904.01 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:    55   95  78.6     61     313
Waiting:       22   62  78.7     28     280
Total:         55   95  78.6     61     313

Percentage of the requests served within a certain time (ms)
  50%     61
  66%     64
  75%     69
  80%    144
  90%    282
  95%    313
  98%    313
  99%    313
 100%    313 (longest request)

Another run from tin, this time with gzip accept:

ab -H 'Accept-encoding: gzip' -n200 'http://en.wikipedia.org/w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama'
Percentage of the requests served within a certain time (ms)
  50%    873
  66%    970
  75%   1040
  80%   1063
  90%   1178
  95%   1235
  98%   1468
  99%   1884
 100%   2386 (longest request)
ab -H 'Accept-encoding: gzip' -n200 http://parsoid-lb.eqiad.wikimedia.org/enwiki/Barack_Obama?oldid=643768869
Percentage of the requests served within a certain time (ms)
  50%     29
  66%     30
  75%     31
  80%     31
  90%     32
  95%     32
  98%     34
  99%     36
 100%     36 (longest request)

Didn't we run into this before once and decide to wipe the varnish parsoid caches to alleviate something that built up over time or something like that?

@BBlack, the results show Varnish being fairly fast while retrieving the same content through the PHP API is a lot slower. It is not a Parsoid Varnish problem, but could be a problem in the API Varnishes, HHVM or the fcgi interface with Apache.

Another run from the VPS:

ab -H 'Accept-encoding: gzip' -n200 'http://en.wikipedia.org/w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama'

Complete requests:      200
Failed requests:        74
   (Connect: 0, Receive: 0, Length: 74, Exceptions: 0)
Total transferred:      103850364 bytes
HTML transferred:       103722072 bytes

Percentage of the requests served within a certain time (ms)
  50%   2313
  66%   2399
  75%   2477
  80%   2514
  90%   2596
  95%   2688
  98%   2824
  99%   3027
 100%   3445 (longest request)

Note that some requests are failing for some reason.

Again, direct requests to the Parsoid Varnishes are faster:

ab -H 'Accept-encoding: gzip' -n200 http://parsoid-lb.eqiad.wikimedia.org/enwiki/Barack_Obama?oldid=643768869
Percentage of the requests served within a certain time (ms)                                      
  50%    516                                                                                      
  66%    535                                                                                      
  75%    537                                                                                      
  80%    539                                                                                      
  90%    541                                                                                      
  95%    574                                                                                      
  98%    611                                                                                      
  99%    683                                                                                      
 100%    904 (longest request)

From the office:

ab -H 'Accept-encoding: gzip' -n200 'http://en.wikipedia.org/w/api.php?format=json&uselang=en&action=visualeditor&paction=parse&page=Barack_Obama'
Complete requests:      200                                                                       
Failed requests:        118                                                                       
   (Connect: 0, Receive: 0, Length: 118, Exceptions: 0)                                           
Total transferred:      103931795 bytes                                                           
HTML transferred:       103803104 bytes

Percentage of the requests served within a certain time (ms)
  50%   2195
  66%   2310
  75%   2391
  80%   2417
  90%   2471
  95%   2586
  98%   2648
  99%   2759
 100%   2851 (longest request)
ab -H 'Accept-encoding: gzip' -n200 http://parsoid-lb.eqiad.wikimedia.org/enwiki/Barack_Obama?oldid=643768869
Failed requests:        0
Percentage of the requests served within a certain time (ms)
  50%    686
  66%    691
  75%    694
  80%    695
  90%    730
  95%    823
  98%   1121
  99%   1522
 100%   2601 (longest request)
This comment was removed by GWicke.

Across 1000 pairs of *image requests* (thumb.php), it seems that transfer times don't differ significantly between cached & uncached requests (with connect_mean meaning mean time to first bytes / headers):

{ uncached: 
   { connect_mean: 1295.051,
     end_mean: 1392.996,
     transfer_mean: 97.945 },
  cached: 
   { connect_mean: 13.585,
     end_mean: 101.113,
     transfer_mean: 87.528 } }

This means that there doesn't seem to be a general throughput issue with HHVM (assuming thumb.php hits HHVM).

For Parsoid content, loading Obama through the PHP API adds about 1s latency over going direct. The reason for the larger differences observed from slower connections is not clear yet.

marcoil lowered the priority of this task from High to Medium.Feb 10 2015, 3:05 PM
marcoil moved this task from Performance to html2wt on the Parsoid board.
marcoil moved this task from html2wt to VE Q3 on the Parsoid board.
marcoil raised the priority of this task from Medium to High.Feb 10 2015, 3:08 PM

So, what is the ask here? Trivially, piping an HTTP request through PHP is going to be slow, but in return it reduces complexity and the number of calls made by the client.

@Jdforrester-WMF: My original measurements indicated a significantly larger performance differential than expected just from going through PHP. Subsequent measurements showed different timings, and it is not quite clear to me what caused the original performance differential. At the very least, this is something we should keep an eye on.

In any case, the measurements also suggest that for larger pages retrieving the HTML content directly (without bundling it in JSON in the PHP API) would save about 1-2s of loading time, just by starting the bulk of the download earlier. I believe the added complexity would be fairly limited in VE (one more parallel request), so it might be an easy win.

Failed requests:        118

This is curious as well.

Across 1000 pairs of *image requests* (thumb.php), it seems that transfer times don't differ significantly between cached & uncached requests

These directly hit the image scalers, which are still on Zend.

We just tracked the mysterious throughput issue down to output buffering in HHVM being slow at times, which I think Ori is summarizing right now.

This comment was removed by ori.
Jdforrester-WMF renamed this task from API requests to action=visualeditor&paction=parse more than four times slower than requests directly to parsoid-lb to Load the edit HTML without wrapping it in JSON via the API.Mar 10 2015, 10:46 PM

@ori, did we ever fully track down the apparent HHVM / output buffer issue? Would be good to not lose track of that issue.

Re-opening so that we don't lose track of the HHVM issue.

GWicke renamed this task from Load the edit HTML without wrapping it in JSON via the API to Performance issue in HHVM with output buffer?.Mar 20 2015, 11:17 PM

Since we long ago deployed an output streaming support patch to HHVM, I guess this is resolved?

Joe edited a custom field.