4x longer execution time in 3.14.1

[awisur]

HHVM Version

hhvm-nightly from http://dl.hhvm.com/ubuntu/dists/xenial/main/ (08. June 2016) Compared to: HipHop VM 3.12.1 (rel) Compiler: tags/HHVM-3.12.1-0-gf516f1bb9046218f89885a220354c19dda6d8f4d Repo schema: f2e5f39b2ad4a08bcbd90b5d8bcb580f40fba6c8

Standalone code, or other way to reproduce the problem

function test_Loops($count = 4000000) {
    global $multiplier;
    $count = $count * $multiplier;
    $time_start = microtime(true);
    for($i = 0; $i < $count; ++$i);
    $i = 0; while($i < $count) ++$i;
    return number_format(microtime(true) - $time_start, 3);
}

function test_IfElse($count = 2000000) {
    global $multiplier;
    $count = $count * $multiplier;
    $time_start = microtime(true);
    for ($i=0; $i < $count; $i++) {
        if ($i == -1) {
        } elseif ($i == -2) {
        } else if ($i == -3) {
        }
    }
    return number_format(microtime(true) - $time_start, 3);
} 

Expected result

Same or improved speed in the nightly build.

Actual result

The nightly build uses 4x more time for the looping and if/else test

[jwatzman]

• Any chance you could bisect this?
• You mention this is a regression in the nightly vs 3.12, but you are using the xenial nightlies -- we never did an official xenial release for 3.12. Did you run 3.12 on xenial? Could it be due to an OS change or build environment change? Have you tried our official builds of 3.12 and our official nightlies on the same OS -- does the issue reproduce there?

[Orvid]

It's worth noting that the Xenial nightlies only just got enabled on Monday, so it's perfectly possible that I've missed part of the configuration. I do know that until at least yesterday (not sure exactly when in relation to when that nightly built) it wasn't building using the system libzip lz4 or quicklz along with missing a couple other libs.

[awisur]

I will set up a new small cloud server, and run the bench on several versions. And we will see the result. I'll keep you posted, but it will be 4-5 hours before i can start with it. I'll update here.

[awisur]

I've tested by running the script 25 times, and discarind the first 20 runs to allow the JIT to work properly.

The following times are averages of run 20-25

SERVER: HipHop VM 3.12.1 (rel) Compiler: tags/HHVM-3.12.1-0-gf516f1bb9046218f89885a220354c19dda6d8f4d Repo schema: f2e5f39b2ad4a08bcbd90b5d8bcb580f40fba6c8

test_ifelse : 0.060 sec. test_loops : 0.068 sec.

SERVER: HipHop VM 3.12.2 (rel) Compiler: tags/HHVM-3.12.2-0-gcfb18092a7ad76b20b9c8dabcb03edd8b14c55cd Repo schema: 8d8091444e7dc037f3c5869a32f94420c3b465f1

test_ifelse : 0.059 sec. test_loops : 0.068 sec.

SERVER: HipHop VM 3.13.2 (rel) Compiler: tags/HHVM-3.13.2-0-g64d6782149a51585d2bdc3b67dd399f2ef630517 Repo schema: 8c57ad2276433d9fafaf454878290df2e75e03a0

test_ifelse : 0.057 sec. test_loops : 0.075 sec.

SERVER: HipHop VM 3.14.0-dev (rel) Compiler: heads/master-0-g01c6e96a002d10f59e506cbdc5dd880a257403b3 Repo schema: 7c584786474ee45428ce3687fd09357d062ea56f

test_ifelse : 0.183 sec. test_loops : 0.202 sec.

[awisur]

This is the exact script I'm running: http://pastebin.com/tKXcrLDM And the machine is a EC2 - m3.medium Ubuntu 14.04 fully updated.

[jwatzman]

That script is a weird microbenchmark. A 4x increase IME isn't that big of a deal, unless you have an example of real-world code with a performance issue that you traced to this root cause? HHVM historically doesn't do well on microbenchmarks, but microbenchmarks like this are not representative of real-world code in most cases (most webapps don't do things like this in a tight loop).

Often times HHVM will actually pessimise code like this which doesn't show up in the real world in order to optimise some other related case. For example, last I knew, access to undeclared members on objects involved an extra one or two pointer indirections in order to save just one lookup for declared variables, since the latter are much more common and so more important to make fast.

Something as silly as microtime getting more expensive would affect your microbenchmark, or incrementing the same variable 10,000 times, etc etc... neither of which are typically on the hot path of any webapp.

[awisur]

I agree that this is a synthetic test and no real world scenario, but loops and if/else in applications are quite common, and a 4x increase in execution time is something you don't want imho.

I will update and compare with the nightly from today, and the 3.14 release later today, and I will post the results here.

[jwatzman]

But it's not necessarily that. Without further investigation (bisect), this could potentially be a regression in

• microtime
• number_format
• for loops without a body
• if statements without a body
• etc etc -- any number of other awkward things that dramatically affect this (and other) microbenchmarks but just don't happen in real code

[jwatzman]

(If you want to bisect this, that would be useful to see if it maybe points at what's really going on.)

[awisur]

Alright I think i figured it out.

I made this script: http://pastebin.com/UhjNYm5F

And ran it as before 25 times. And this is the result:

It seems 3.14 does not optimize the code inside functions.

3.14.1

RUNNING TESTS GLOBALLY

TEST A: Empty for loop Test - Time used: 0.012 TEST B: Empty while loop test - Time used: 0.004 TEST C: If/else in for loop test - Time used: 0.017 TEST D: If/else in while loop test - Time used: 0.017

RUNNING TESTS INSIDE FUNCTIONS

TEST A: Empty for loop Test inside function - Time used: 0.029 TEST B: Empty while loop test inside function- Time used: 0.021 TEST C: If/else in for loop test inside function - Time used: 0.092 TEST D: If/else in while loop test inside function - Time used: 0.088

3.12.2

RUNNING TESTS GLOBALLY

TEST A: Empty for loop Test - Time used: 0.004 TEST B: Empty while loop test - Time used: 0.012 TEST C: If/else in for loop test - Time used: 0.017 TEST D: If/else in while loop test - Time used: 0.017

RUNNING TESTS INSIDE FUNCTIONS

TEST A: Empty for loop Test inside function - Time used: 0.001 TEST B: Empty while loop test inside function- Time used: 0.001 TEST C: If/else in for loop test inside function - Time used: 0.002 TEST D: If/else in while loop test inside function - Time used: 0.002

As you can see 3.14 does not optimize the code inside a function even closely to how 3.12.2 does it.

[sibest]

awisur could you try your benchmark with hhvm 3.13.1?

[awisur]

Here are the same bench run on both 3.13.1 and 3.13.2

Downloaded the packages from here: http://dl.hhvm.com/ubuntu/pool/main/h/hhvm/

3.13.1

RUNNING TESTS GLOBALLY

TEST A: Empty for loop Test - Time used: 0.004 TEST B: Empty while loop test - Time used: 0.004 TEST C: If/else in for loop test - Time used: 0.021 TEST D: If/else in while loop test - Time used: 0.017

RUNNING TESTS INSIDE FUNCTIONS

TEST A: Empty for loop Test inside function - Time used: 0.001 TEST B: Empty while loop test inside function- Time used: 0.001 TEST C: If/else in for loop test inside function - Time used: 0.003 TEST D: If/else in while loop test inside function - Time used: 0.002

3.13.2

RUNNING TESTS GLOBALLY

TEST A: Empty for loop Test - Time used: 0.004 TEST B: Empty while loop test - Time used: 0.004 TEST C: If/else in for loop test - Time used: 0.020 TEST D: If/else in while loop test - Time used: 0.017

RUNNING TESTS INSIDE FUNCTIONS

TEST A: Empty for loop Test inside function - Time used: 0.001 TEST B: Empty while loop test inside function- Time used: 0.001 TEST C: If/else in for loop test inside function - Time used: 0.002 TEST D: If/else in while loop test inside function - Time used: 0.003

[sibest]

I'm running HHVM to run the game server of my games, Mitos.is: The Game, Worm.is: The Game and Strike.is. The game server is a standalone codebase. I can confirm that HHVM 3.14, using repo.authoritative=true runs 4x slower than hhvm 3.10. hhvm 3.10 is about 30% faster than hhvm 3.11. No speed difference between 3.11, 3.12 and 3.13.

[sibest]

The test i've made is much more complex than an empty loop, i've loaded 1000 entities in the battle field and measured the frame time.

[Orvid]

@sibest Is it a private or public codebase? If you're on IRC we might be able to help track down the cause.

[sibest]

Ok, and i've a question, could you provide me a compiled version of HHVM 3.10 with this patch applied https://github.com/facebook/hhvm/issues/6502 ? For Ubuntu 14.04 trusty. Thank you

[Orvid]

If you're on the IRC, we can probably manage that.

[Orvid]

Looking at that specific change, it doesn't look like it will apply readily to 3.10, there are simply too many changes to the JIT between when 3.10 was released and when that commit was pushed.

[awisur]

3.15.0

RUNNING TESTS GLOBALLY

TEST A: Empty for loop Test - Time used: 0.004 TEST B: Empty while loop test - Time used: 0.004 TEST C: If/else in for loop test - Time used: 0.019 TEST D: If/else in while loop test - Time used: 0.017

RUNNING TESTS INSIDE FUNCTIONS

TEST A: Empty for loop Test inside function - Time used: 0.025 TEST B: Empty while loop test inside function- Time used: 0.025 TEST C: If/else in for loop test inside function - Time used: 0.084 TEST D: If/else in while loop test inside function - Time used: 0.088

[awisur]

3.18.0

RUNNING TESTS GLOBALLY

TEST A: Empty for loop Test - Time used: 0.002 TEST B: Empty while loop test - Time used: 0.003 TEST C: If/else in for loop test - Time used: 0.010 TEST D: If/else in while loop test - Time used: 0.011

RUNNING TESTS INSIDE FUNCTIONS

TEST A: Empty for loop Test inside function - Time used: 0.025 TEST B: Empty while loop test inside function- Time used: 0.024 TEST C: If/else in for loop test inside function - Time used: 0.086 TEST D: If/else in while loop test inside function - Time used: 0.089