HHVM emit profile-translations using a worker pool

[lswith]

HHVM Version: 3.18.1 LTS

Context

There have been some incredibly large spikes when the HHVM server first boots up (within the first 12 requests). I ran some profiling on this and determined this to be the JIT compiling the code. I'm surprised that the JIT compilation can't be out of band (le'ts leave that for a discussion in a seperate thread).

Results

When I turned the JIT off these huge spikes went away and increased stability. The interesting thing was that the response times were identical before and after. This implies that either our codebase is so bad the JIT is completely useless or that the JIT has no real benefit.

I decided to do some more testing and used the symfony demo app which I assumed would be a reasonable codebase to see a noticeable change between turning the JIT on and off. This was also proved wrong. The JIT had no real benefit here either.

Help?!

I was wondering if there was a way to prove that the JIT is working and has benefit?

I'd also like to see the codebase where the JIT is benefiting so that I can compare ours to determine the best way to write performant code.

Configuration

If possible, could the configuration of a performant JIT also be shared? I tried changing multiple configuration options to see if the performance was simply a configuration problem but this approach led nowhere.

[mofarrell]

To start, the JIT compilation is out of band, here is a post talking about that http://hhvm.com/blog/2017/03/23/concurrent-jit-compilation.html.

How many cores does your machine have? The concurrent JIT could consume all you machines resources while compiling code. This would slow down the thread serving the request as well. I believe you can control the concurrency of the JIT using the option hhvm.jit_threads. This is defaulting to 4 at the moment. Additionally, hhvm.jit_worker_threads might also be interesting. I believe that setting is different, in that it controls the concurrency of the retranslation process from profile translations to optimized translations (see PGO http://hhvm.com/blog/2017/02/17/region-jit.html).

To prove the JIT has value you can use our oss-performance benchmarking suite (https://github.com/hhvm/oss-performance). On a site like wordpress the JIT is more than 2 times faster than interp mode. This is measured as throughput of the server (requests per second) not response time, although response time should improve as well. The throughput is a better measure of performance, because websites spend the majority of a request doing IO (database access etc.). Effectively the response time really ends up measuring how often a request got stalled. Measuring throughput avoids this because the OS can schedule other work to happen during IO stalls. If response time is what you care about, HHVM and Hack allow you to improve it by decreasing time spent stalled. Read about the cooperative multitasking model here http://hhvm.com/blog/7091/async-cooperative-multitasking-for-hack.

[lswith]

So running the OSS-Performance tool has lead to some results. It is clear that the JIT has benefit when it comes to throughput.
The only issue I have now is with the large response times when the JIT is turned on. The OSS Tool shows this data but doesn't write it to the summary results after a batch run. I've included it here for reference.

The configuration for the batch run is here:

{
  "runtimes": {
    "HHVM 3.18": {
      "type": "hhvm",
      "bin": "hhvm"
    },
    "HHVM 3.18 (norepo auth)": {
      "type": "hhvm",
      "bin": "hhvm",
      "args": [
        "--no-repo-auth",
        "--i-am-not-benchmarking"
      ]
    },
    "HHVM 3.18 (norepo auth + no jit)": {
      "type": "hhvm",
      "bin": "hhvm",
      "args": [
        "--no-repo-auth",
        "--i-am-not-benchmarking",
	"--no-jit"
      ]
    }
  },
  "targets": [
    "wordpress"
  ],
  "settings": {
    "username": "REDACTED",
    "password": "REDACTED",
    "options": [
      "cpu-fraction=0.5",
      "i-am-not-benchmarking"
    ]
  }
}

As you can see, the longest transaction for a single user hitting hhvm is huge for both HHVM with and without repo-auth. The only time this comes down is when hhvm is running interpretted code. This is why I initially thought the JIT was running synchronously.

*****************************************
** 2017-03-26 19:43:09 EDT
** Configuration: WordpressTarget on hhvm

**************************
** 2017-03-26 19:43:09 EDT
** Installing framework

**************************
** 2017-03-26 19:43:09 EDT
** There is no setUpTest

**************************
** 2017-03-26 19:43:09 EDT
** Starting Nginx
nginx: [alert] could not open error log file: open() "/var/log/nginx/error.log" failed (13: Permission denied)

**************************
** 2017-03-26 19:43:09 EDT
** Starting PHP Engine
running hphp...
all files saved in /tmp/hhvm-nginxW1ohNr ...
running hphp took 0'10" (10321527 us) wall time

**************************
** 2017-03-26 19:43:22 EDT
** Unfreezing framework

**************************
** 2017-03-26 19:43:22 EDT
** Running sanity check

*******************************************
** 2017-03-26 19:43:22 EDT
** Starting Siege for single request warmup
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 1 concurrent users for battle.
The server is now under siege...
done.

Transactions:		         314 hits
Availability:		      100.00 %
Elapsed time:		       20.43 secs
Data transferred:	        8.48 MB
Response time:		        0.06 secs
Transaction rate:	       15.37 trans/sec
Throughput:		        0.42 MB/sec
Concurrency:		        1.00
Successful transactions:         299
Failed transactions:	           0
Longest transaction:	        8.44
Shortest transaction:	        0.00


******************************************
** 2017-03-26 19:43:42 EDT
** Starting Siege for multi request warmup
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 200 concurrent users for battle.
The server is now under siege...

Lifting the server siege...      done.

Transactions:		        6958 hits
Availability:		      100.00 %
Elapsed time:		       59.99 secs
Data transferred:	      197.15 MB
Response time:		        1.70 secs
Transaction rate:	      115.99 trans/sec
Throughput:		        3.29 MB/sec
Concurrency:		      197.42
Successful transactions:        6575
Failed transactions:	           0
Longest transaction:	       17.54
Shortest transaction:	        0.13


****************************
** 2017-03-26 19:44:43 EDT
** Clearing nginx access.log

*******************************
** 2017-03-26 19:44:43 EDT
** Starting Siege for benchmark
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 200 concurrent users for battle.
The server is now under siege...

Lifting the server siege...      done.

Transactions:		        7567 hits
Availability:		      100.00 %
Elapsed time:		       59.86 secs
Data transferred:	      204.67 MB
Response time:		        1.56 secs
Transaction rate:	      126.41 trans/sec
Throughput:		        3.42 MB/sec
Concurrency:		      196.78
Successful transactions:        7213
Failed transactions:	           0
Longest transaction:	       22.10
Shortest transaction:	        0.75


**************************
** 2017-03-26 19:45:43 EDT
** Collecting results

**************************
** 2017-03-26 19:45:43 EDT
** Collecting TC/PCRE data

***************************
** 2017-03-26 19:45:49 EDT
** There is no tearDownTest

*****************************************
** 2017-03-26 19:45:55 EDT
** Configuration: WordpressTarget on hhvm

**************************
** 2017-03-26 19:45:55 EDT
** Installing framework

**************************
** 2017-03-26 19:45:55 EDT
** There is no setUpTest

**************************
** 2017-03-26 19:45:55 EDT
** Starting Nginx
nginx: [alert] could not open error log file: open() "/var/log/nginx/error.log" failed (13: Permission denied)

**************************
** 2017-03-26 19:45:55 EDT
** Starting PHP Engine

**************************
** 2017-03-26 19:45:57 EDT
** Unfreezing framework

**************************
** 2017-03-26 19:45:59 EDT
** Running sanity check

*******************************************
** 2017-03-26 19:45:59 EDT
** Starting Siege for single request warmup
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 1 concurrent users for battle.
The server is now under siege...
done.

Transactions:		         314 hits
Availability:		      100.00 %
Elapsed time:		       21.13 secs
Data transferred:	        8.48 MB
Response time:		        0.07 secs
Transaction rate:	       14.86 trans/sec
Throughput:		        0.40 MB/sec
Concurrency:		        1.00
Successful transactions:         299
Failed transactions:	           0
Longest transaction:	        8.27
Shortest transaction:	        0.00


******************************************
** 2017-03-26 19:46:20 EDT
** Starting Siege for multi request warmup
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 200 concurrent users for battle.
The server is now under siege...

Lifting the server siege...      done.

Transactions:		        6907 hits
Availability:		      100.00 %
Elapsed time:		       59.41 secs
Data transferred:	      196.00 MB
Response time:		        1.69 secs
Transaction rate:	      116.26 trans/sec
Throughput:		        3.30 MB/sec
Concurrency:		      196.75
Successful transactions:        6520
Failed transactions:	           0
Longest transaction:	       12.81
Shortest transaction:	        0.17


****************************
** 2017-03-26 19:47:20 EDT
** Clearing nginx access.log

*******************************
** 2017-03-26 19:47:20 EDT
** Starting Siege for benchmark
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 200 concurrent users for battle.
The server is now under siege...

Lifting the server siege...      done.

Transactions:		        7058 hits
Availability:		      100.00 %
Elapsed time:		       59.69 secs
Data transferred:	      199.16 MB
Response time:		        1.66 secs
Transaction rate:	      118.24 trans/sec
Throughput:		        3.34 MB/sec
Concurrency:		      196.67
Successful transactions:        6712
Failed transactions:	           0
Longest transaction:	       12.52
Shortest transaction:	        0.70


**************************
** 2017-03-26 19:48:20 EDT
** Collecting results

**************************
** 2017-03-26 19:48:20 EDT
** Collecting TC/PCRE data

***************************
** 2017-03-26 19:48:30 EDT
** There is no tearDownTest

*****************************************
** 2017-03-26 19:48:35 EDT
** Configuration: WordpressTarget on hhvm

**************************
** 2017-03-26 19:48:35 EDT
** Installing framework

**************************
** 2017-03-26 19:48:36 EDT
** There is no setUpTest

**************************
** 2017-03-26 19:48:36 EDT
** Starting Nginx
nginx: [alert] could not open error log file: open() "/var/log/nginx/error.log" failed (13: Permission denied)

**************************
** 2017-03-26 19:48:36 EDT
** Starting PHP Engine

**************************
** 2017-03-26 19:48:38 EDT
** Unfreezing framework

**************************
** 2017-03-26 19:48:38 EDT
** Running sanity check

*******************************************
** 2017-03-26 19:48:38 EDT
** Starting Siege for single request warmup
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 1 concurrent users for battle.
The server is now under siege...
done.

Transactions:		         314 hits
Availability:		      100.00 %
Elapsed time:		       12.34 secs
Data transferred:	        8.48 MB
Response time:		        0.04 secs
Transaction rate:	       25.45 trans/sec

�
Throughput:		        0.69 MB/sec
Concurrency:		        1.00
Successful transactions:         299
Failed transactions:	           0
Longest transaction:	        0.06
Shortest transaction:	        0.00


******************************************
** 2017-03-26 19:48:51 EDT
** Starting Siege for multi request warmup
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 200 concurrent users for battle.
The server is now under siege...

Lifting the server siege...      done.

Transactions:		        3222 hits
Availability:		      100.00 %
Elapsed time:		       59.95 secs
Data transferred:	       89.04 MB
Response time:		        3.60 secs
Transaction rate:	       53.74 trans/sec
Throughput:		        1.49 MB/sec
Concurrency:		      193.44
Successful transactions:        3240
Failed transactions:	           0
Longest transaction:	        5.35
Shortest transaction:	        0.32


****************************
** 2017-03-26 19:49:51 EDT
** Clearing nginx access.log

*******************************
** 2017-03-26 19:49:51 EDT
** Starting Siege for benchmark
siege: unrecognized option '--no-parser'
siege: unrecognized option '--no-parser'
** SIEGE 3.1.1
** Preparing 200 concurrent users for battle.
The server is now under siege...

Lifting the server siege...      done.

Transactions:		        2981 hits
Availability:		      100.00 %
Elapsed time:		       59.89 secs
Data transferred:	       86.14 MB
Response time:		        3.91 secs
Transaction rate:	       49.77 trans/sec
Throughput:		        1.44 MB/sec
Concurrency:		      194.48
Successful transactions:        3083
Failed transactions:	           0
Longest transaction:	        7.42
Shortest transaction:	        1.10


**************************
** 2017-03-26 19:50:51 EDT
** Collecting results

**************************
** 2017-03-26 19:50:51 EDT
** Collecting TC/PCRE data

***************************
** 2017-03-26 19:50:54 EDT
** There is no tearDownTest

[lswith]

another way to induce this delay is to run the oss-performance tool and effectively not preform a warmup. Using the wait-after-warmup flag and the skip-warmup flag allowed me to run my own script to prove there is a substantial delay when the JIT is running.

hhvm perf.php --hhvm=$(which hhvm) --wordpress --skip-warmup --verbose --i-am-not-benchmarking --no-repo-auth --wait-after-warmup

Once the server is ready for responses, simply running the command:
for i in $(seq 1 50); do curl -s -S -k -w '%{time_total}\n' -o /dev/null http://127.0.0.1:8092/; done gives these kind of results:

0.054
0.052
0.052
0.052
0.053
0.053
0.052
11.145 <---- JIT kicking in
0.027
0.026
0.028
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.027
0.027
0.027
0.027
0.026
0.027
0.027
0.027
0.027
0.028
0.027
0.026
0.027
0.026
0.026
0.026
0.026
0.027
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026
0.026

The huge jump at the 8th request is the interesting one.

[mofarrell]

There is a setting, hhvm.jit_profile_interp_requests (its default is 11). The JIT kicks in on the 12th request. You see it happening on the 8th, because the setup and the sanity check already sent 4 requests. The reason it is slow is that the initial JIT process does not occur as "out of band" as we might like (I know I said that it was earlier, but it only is for certain translation types). In order to know when a tracelet ends and the next one starts we must JIT it. At the start of each tracelet we also want to know the types of variables used in the tracelet, and because PHP is dynamically typed we don't know them unless there is a request running. This means we can't easily schedule the work to be done out of band. We might look at improving in the long run, however it has minimal impact on a server that is running for an extended period of time. The advantage of the JIT comes at a small cost, the cost of warming up the server. These requests that timeout, or take longer are part of the warmup. If you want to hide the pain of these warmup requests from actual users, you can setup a warmup script that exercises your code, and allows it to generate some translations before serving live requests. Here is an issue documenting some warmup functionality built in to HHVM #5312