bellard
Implements Javascript profiling support.
This pull request addresses #183 and builds upon the ideas introduced in #184, taking a slightly different approach to enhance flexibility and functionality:
- Profiling configuration is achieved by providing callback functions and optional opaque data. QuickJS will invoke these callbacks with relevant atoms for the function name and filename, along with the provided opaque data (e.g., a file handle for writing output). If possible, the function name includes the constructor of the "this" object, adding context. Unlike #184, which logs stats directly to stderr, this implementation offers greater flexibility by enabling client applications to massage the data in different ways (computing aggregated statistics, logging the raw events, etc).
- In #184, logging occurred in the bytecode destructor, which often led to function name atoms being collected prematurely, resulting in many functions being logged as
<:isGone:>. This implementation resolves that by reporting profiling data at function entry and exit, ensuring the function name remains valid. Additionally, this approach includes context for functions (e.g., the constructor of thethisobject, akin to V8 stack traces for disambiguation) and flags anonymous functions explicitly. - The qjs binary demonstrates an example usage of the profiling API by producing output in a format compatible with Chrome DevTools, chrome://tracing and tools like Perfetto. By default, every call is logged, though the API (and qjs) supports configurable sampling. Here is an example of running
./qjs -p profile.json examples/pi_bigint.js 20and then opening profile.json in the Chrome Dev Tools:
Please note that I'm not super familiar with QuickJS yet. I downloaded the code this week and have been playing with it only for a couple of days. Let me know if there are better ways to do some of the things I'm doing here, or if there is a coding style guide this change should adhere to.
Thanks!
By the way, the current implementation in the qjs program is super naive, issuing an fwrite on every function start/end, which is expensive and likely skewing the measurements (especially since fwrite does buffering and some calls will get an arbitrary penalty when hitting the disk).
If qjs is used in production environments and not just as an example of how to use the quickjs library (I don't know, please tell me), I could change the implementation to collect the events in memory and write them at the end instead. I've already written that code for my own application so it's just a matter of porting it from C++ to C.
This is excellent, thanks Rubén. You published it just in time for something I needed. ¡Moitas grazas!
I ran into some issues probably due to embedding quickjs through quickjspp instead of running in qjs.
Issues
⚠️ The most important one: I'm getting garbled names coming from random location pointers, which crash the visual tools (specially '\n's).
Quickjspp adds C++-side functions to JS as getters, I think.
My program does reentry C++ loop -> JS frame -> C++ bound funcs, in case that's relevant.
I worked around that sanitizing for the time being because I didn't have time to dig into the qjs codebase and figure out what went wrong. Definitely not great for overhead but still helped me a lot.
void sanitize(const char* in, char* out, int n) {
n--;
for (int i = 0; *in && i < n; i++) {
*(out++) = isprint(*in) ? *in : 'X';
in++;
}
*out = 0;
}
//...
char ok[128];
sanitize(func_str2, ok, 128);
Tools
First the good news, ui.perfetto.dev works perfectly well, even with a lot of data and some OOM crashes.
Chrome Tools' profiler on the other hand is really bad at loading the profile. I’m getting: Malformed timeline data: SyntaxError: Unexpected end of JSON input even when it's definitely not malformed and still loads partially, approximately only the first 4 seconds of a 120 seconds run at a 1.5GB file. And forget about loading a file >2GB due to 32 (31?) bit limits.
Patching quickjspp
As quickjspp integrates quickjs manually without subtrees/submodules I'll leave this script to patch and build quickjspp for reference in case anyone wants to try this great profiler out and is in the same situation as I am.
#!/bin/bash
mkdir -p temp
git clone https://github.com/rubenlg/quickjs.git temp/quickjs-profiling
cd temp/quickjs-profiling/
git checkout profiling
git diff master >../quickjs-profiling.patch
cd ../../quickjspp/
git apply -v ../temp/quickjs-profiling.patch --directory=quickjs --reject --whitespace=fix
if [ ! -f CMakeLists.txt.profbak ]; then
cp CMakeLists.txt CMakeLists.txt.profbak
echo "set_property(DIRECTORY quickjs PROPERTY COMPILE_DEFINITIONS CONFIG_PROFILE_CALLS=1)" >>CMakeLists.txt
fi
mkdir -p build
cd build
cmake ..
cmake --build .
I also had problems with loading large profile traces in Chrome Profiler. I ended up creating a tree of calls in memory and pruning the fast branches (those that take less than 0.1 ms to execute) before writing the file. This made the file much smaller and more manageable. I didn't do any of that for the qjs binary in this PR, though.
The garbled names could be caused by how quickjspp maps the C++ API to quickjs. I can't reproduce that myself. When I expose C++ functions and classes to quickjs, I control the names I give them, and that's what I get back in the profiles. I also do multiple jumps between C++ and Javascript and yet the profiles are clean.
I had some time today and I figured out the issue, get_full_func_name can return JS_ATOM_NULL (0), passed on to JS_AtomToCString at profile_function_start/end which in both cases won't null check (it even calls JS_DupValue making quickjs refcount ...something 😱)
static JSAtom get_full_func_name(JSContext *ctx, JSValueConst func, JSValueConst this_obj)
{
JSAtom result_atom;
const char *func_str = get_func_name(ctx, func);
if (!func_str || func_str[0] == '\0') {
JS_FreeCString(ctx, func_str);
return JS_ATOM_NULL;
}
//...