Thanks for the quick/helpful response!
> Not seeing a difference there makes sense; the GC doesn't care about
> yielding to the event loop.
>
Ah, I didn't know that! I'll update my notes.
That means 20ms were spent on the main thread some time in the past, 115
> ms in the background, and then 2 ms on the main thread just now (so those 2
> ms would be part of the 37 ms of that turn).
When running on a 1-CPU machine, wouldn't this mean that the time in the
past/background could interrupt my code when I'm running a user's update
function? Is there any way for me to check that? I got the 137-ms figure by
manually summing all of the reported optimization steps that were logged.
--minimal and --predictable
>
Sorry, I should have clarified; I tried those flags as a means of further
pointing to optimization as the cause, not as a solution to my problem.
I.e. when running with "--minimal", there shouldn't be any optimizations
done, which is why my individual functions did indeed sum to the total
execution time that I'd measured.
One thing you could try is wrapping the whole thing into a website so you
> can use Chrome DevTools' profiling facilities. Maybe that'll make it easier
> to drill down into those rarely-occurring delays.
>
Thankfully, it's already a web game, so I'll go check this out now and see
if it'll tell me more than Node's profiler did.
On Friday, January 18, 2019 at 12:58:21 PM UTC-8, Jakob Kummerow wrote:
>
> Answering what I can:
>
> I changed my code from using a "while(true)" loop to calling
>> "setImmediate" every once in a while so that it would yield to the event
>> loop, that way the GC shouldn't interrupt a turn while it's executing. I
>> didn't notice a difference doing this.
>
>
> Not seeing a difference there makes sense; the GC doesn't care about
> yielding to the event loop.
>
> apparently 137 ms were spent optimizing (20 ms to prepare, 115 ms to
>> execute, and 2 ms to finalize).
>
>
> That means 20ms were spent on the main thread some time in the past, 115
> ms in the background, and then 2 ms on the main thread just now (so those 2
> ms would be part of the 37 ms of that turn).
>
> Running that same test with "--minimal"
>
>
> You mean V8's --minimal flag? That is absolutely not what you want. It's a
> development tool that turns off everything except the bare minimum: no more
> type feedback, no more optimizing compiler, >100x performance hit. (And
> FWIW, that flag has recently been removed.)
>
> I tried "--predictable" without seeing any differences
>
>
> Yes, --predictable is another development/debugging tool that is not
> useful for production purposes. It turns off all sources of randomness,
> which includes all threading. You would only see worse performance and
> longer main-thread stalls from this.
>
> Are there any other V8 flags that may be of help here?
>
>
> The default configuration is the recommended configuration for best
> performance.
>
> Is it possible to choose when to run optimizations?
>
>
> Effectively no. (There is the special intrinsic
> %OptimizeFunctionOnNextCall, which does what the name suggests, but
> optimization is only useful if the right type feedback is available, so
> manually choosing when to optimize a given function only makes sense for
> tests where you know exactly which function you want to have optimized
> when; I can't imagine it being useful for your use case: especially for
> user-provided code, there is no way to tell when it is ready for
> optimization, and if you manually optimize it too early, it'll just get
> deoptimized right away, so the manually triggered optimization would be a
> waste of time and only introduce more/longer delays.)
>
> Based on the data you've provided, I'm not convinced that optimizations
> are the reason for those long turns, but I also don't have a good guess for
> what else it might be.
>
> If it were optimizations, then warmup would probably be the best
> mitigation, but you report that warmup doesn't help, so it's probably
> something else. The same reasoning speaks against the other
> frequently-given advice, which is to avoid deoptimizations at least in the
> code you control (while deopts themselves are fast, a deoptimized function
> might get optimized again later, and that might take time).
>
> One thing you could try is wrapping the whole thing into a website so you
> can use Chrome DevTools' profiling facilities. Maybe that'll make it easier
> to drill down into those rarely-occurring delays.
>
>
> On Fri, Jan 18, 2019 at 12:19 PM Adam Damiano <onai...@gmail.com
> <javascript:>> wrote:
>
>> I've tried to be as descriptive as possible below without covering
>> irrelevant details. The summary of the problem is that I think V8
>> optimizations may be causing unpredictable processing spikes in my game
>> that I need to be able to either defer or measure.
>>
>> Background
>>
>> - The code is closed-source, and there are a *lot* of moving parts,
>> so I'm wondering mostly about theory here and not necessarily
>> implementation. More on this in the "Questions" section at the bottom.
>> - I'm making a game where players write code for bots that battle
>> each other. The game is turn-based, and each match can take thousands of
>> turns. All of these turns get simulated at once in a NodeJS process
>> (v10.15) running in a 1-vCPU Alpine container on AWS. After a simulation
>> is
>> done, the battle is essentially replayed on the client without any input
>> from the player.
>> - Each simulation is CPU-intensive given that it's just running
>> player-defined code. There is no network or disk utilization during this
>> time. The most important performance metrics for me are:
>> - How long (in milliseconds) does an average turn take to simulate?
>> - How long does the longest turn take to simulate?
>> - The average is important so that I know how many turns to limit
>> matches to. The measured average over tens of thousands of real matches
>> was
>> about 0.3 ms/turn, so I chose 3000 turns for the limit since 0.3 ms/turn
>> *
>> 3000 turns is still less than a second (which I consider to be a
>> reasonable
>> amount of time for players to have to wait for a result).
>> - The longest turn is important so that I can figure out when to stop
>> executing scripts that will probably never complete on their own. For
>> example, if someone writes an infinite loop, then I need to cut the
>> execution off *somewhere*. I chose 50ms for this.
>> - Code is executed using "eval" (I know about the security risks and
>> have hopefully mitigated any attacks, but I want this issue to stay
>> focused
>> on performance rather than security). Here is a simplified version of the
>> steps that I run, but the summary is that I "eval" a user-defined
>> function
>> once, then I can call that function multiple times per match:
>> - Give each bot a "namespace" for the user to put their code into:
>> global.bot1 = {};
>> global.bot2 = {};
>> ...
>> global.botN = {};
>>
>>
>> - Get code from the user for a particular bot:
>> const exampleUserDefinedScript = `update = function() {
>> fireLasers();
>> };`;
>>
>>
>> - Transform it slightly to be able to place it into one of the
>> namespaces:
>> const exampleUserDefinedScript = `global.bot1.update = function() {
>> fireLasers();
>> };`;
>>
>>
>> - Evaluate that to put it into my global scope:
>>
>> eval(exampleUserDefinedScript);
>>
>>
>> - Simulate a match in a loop using those global functions:
>>
>> while (true) {
>> const bot = findNextBotToUpdate();
>> global[bot].update(); // note: this is what is timed to give me my
>> performance metrics
>> if (gameEnded()) break;
>> }
>>
>>
>> - Free references to the global functions:
>>
>> global.bot1 = null;
>> global.bot2 = null;
>> // etc.
>>
>>
>> Problem
>> The problem I'm running into is that individual turns sometimes take
>> longer than 50ms. I investigated heavily (see next section) and I think
>> that it's due to V8 optimizing on the main thread.
>>
>> Investigation
>>
>> - As mentioned, this is running in a container with no other
>> processes, so the only threads that could be interrupting would be from
>> the
>> OS or Node itself.
>> - The environment that I'm running in doesn't seem to matter too
>> much. Running on AWS in a 1-vCPU container is my production environment,
>> but even in development, I see turns that take a disproportionately long
>> time.
>> - I ran the Node profiler
>> <https://nodejs.org/en/docs/guides/simple-profiling/>, but nothing
>> stood out to me. Then again, I could just be interpreting the results
>> incorrectly. I get something like this:
>>
>> Statistical profiling result from converted, (6468 ticks, 126
>> unaccounted, 0 excluded).
>> [Summary]:
>> ticks total nonlib name
>> 3184 49.2% 96.2% JavaScript
>> 0 0.0% 0.0% C++
>> 314 4.9% 9.5% GC
>> 3158 48.8% Shared libraries
>> 126 1.9% Unaccounted
>>
>>
>> - When I run with "--trace-gc", I see that the garbage collector is
>> mostly running scavenges that take 0.0 ms. Regardless, I changed my code
>> from using a "while(true)" loop to calling "setImmediate" every once in a
>> while so that it would yield to the event loop, that way the GC shouldn't
>> interrupt a turn while it's executing. I didn't notice a difference doing
>> this.
>> - Running with --trace-deopt doesn't show any deoptimizations taking
>> a long time.
>> - Running with --trace-opt shows some optimizations taking a long
>> time, but I don't fully understand the results. For example, on one turn
>> that took 37.33 ms (which was 9 times the average for that match), 1 ms
>> was
>> spent deoptimizating, and apparently 137 ms were spent optimizing (20 ms
>> to
>> prepare, 115 ms to execute, and 2 ms to finalize).
>> - I ended up working perfhooks.performance.now() calls all over my
>> code: one set was placed around all of the code that I execute on behalf
>> of
>> the user, and one set was placed into individual function calls that are
>> called by the user. What I saw was that the time spent in individual
>> function calls didn't add up to the total amount of time that I measured.
>> To me, this indicated that the time spent was not a direct result of my
>> JavaScript code, but rather an indirect result (e.g. optimization).
>> - Running that same test with "--minimal" would not reproduce those
>> results. Instead, the sum of the individual times would indeed add up to
>> the total time measured.
>> - I tried "warming up" the optimizations by running ~200 random
>> simulated matches at startup time, but I still ran into long-running
>> turns.
>> This might have been more effective if instead of randomly simulating,
>> I'd
>> exhaustively simulated such that every line of code was being hit.
>>
>>
>> Questions
>>
>> - Is it possible to choose when to run optimizations? For example, I
>> could have them run in between turns, that way I don't count it against a
>> player when optimizations take a while. I realize that it would mean that
>> I'd be running unoptimized code for a turn.
>> - Is it possible to tell exactly how long was spent optimizing from
>> within JavaScript? E.g.
>>
>> const startTime = Date.now();
>> runSomeCode();
>> const elapsedTime = Date.now() - startTime;
>> const timeSpentOptimizing = aV8FunctionThatMayOrMayNotExist(); // can I
>> do something for this?
>> const actualElapsedTime = elapsedTime - timeSpentOptimizing;
>>
>>
>> - Are there any other V8 flags that may be of help here? I tried
>> "--predictable" without seeing any differences, but maybe there's
>> something
>> I'm missing.
>>
>>
>> Thanks for reading through this large blob of text!
>> -Adam
>>
>> --
>> --
>> v8-users mailing list
>> v8-u...@googlegroups.com <javascript:>
>> http://groups.google.com/group/v8-users
>> ---
>> You received this message because you are subscribed to the Google Groups
>> "v8-users" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to v8-users+u...@googlegroups.com <javascript:>.
>> For more options, visit https://groups.google.com/d/optout.
>>
>
--
--
v8-users mailing list
v8-users@googlegroups.com
http://groups.google.com/group/v8-users
---
You received this message because you are subscribed to the Google Groups
"v8-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to v8-users+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
