Can I get high precision timing with EMSDK 4.0.5? #24267

purplesnail · 2025-05-06T06:04:26Z

Hello, I'm testing some C++ code compiled with EMSDK 4.0.5 in NodeJS 20.
I'd like to achieve timing under 1ms, but encountering issues here

I've tried various methods to obtain high precision timing, including using emscripten_get_now and std::chrono::high_resolution_clock::now(), but none have provided precision below 1ms.

I also tried adding compiling flags like -s ENVIRONMENT=node -s PRECISE_F32=1, but they didn't work either.

I understand that there are some security reasons for this, but I'm just wondering if there is a way to overcome this issue?

There was no such issue with emsdk 3.1.22, I upgraded the emsdk recently and noticed this problem.

Thanks.

sbc100 · 2025-05-06T17:40:02Z

We don't any anything in emscripten to alter the precision provided by node.

The emscripten_get_now function compiles just a simple call to node's performance.now() . When I build I simple example I get this in the generated JS:

var _emscripten_get_now = () => performance.now();

As far as I know this has not changed since 3.1.22 so I would not expect to see a difference in the precision. How are you measuring this?

I certainly see sub-millisecond precision under node:

$ cat test.c
#include <stdio.h>
#include <emscripten.h>

int main() {
  while (1) {
    printf("%f\n", emscripten_get_now());
  }
  return 0;
}
$ emcc ./test.c
$ node ./a.out.js
81.863021
96.383032
96.521322
96.585112
96.628512
96.790382
96.845952
96.883412
96.920382
96.975792
97.036242
97.169292
97.219092
97.261072
97.287752
97.319962
97.442012
97.498052
97.537802
97.640382
97.697582
97.808112
97.861322
97.886172
97.908592
97.922302
97.934612
97.951242
97.966462
97.978642
98.001142
98.013632
98.026072
...

sbc100 · 2025-05-06T17:40:44Z

(FYI, PRECISE_F32 doesn't do anything these days).

purplesnail · 2025-05-07T01:29:32Z

Thanks for your reply @sbc100

This is my code:

double t1 = emscripten_get_now();
//do some work
 double t2 = emscripten_get_now();
 printf("[AEC::Process] t1  %f\n", t1);
 printf("[AEC::Process] t2  %f\n", t2);

I want to determine the processing time for some work, so I declared t1 as the start time and t2 as the end time.
But I found that t1 and t2 are often equal, which causes the calculated time to frequently be zero.

Here are the logs — the values after the decimal point are always zero.

Line  1597: 2025-05-07 09:18:40,882 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720827.000000
Line  1602: 2025-05-07 09:18:40,884 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720827.000000
Line  1622: 2025-05-07 09:18:40,893 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720888.000000
Line  1627: 2025-05-07 09:18:40,895 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720888.000000
Line  1647: 2025-05-07 09:18:40,902 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720897.000000
Line  1652: 2025-05-07 09:18:40,904 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720897.000000
Line  1672: 2025-05-07 09:18:40,911 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720906.000000
Line  1677: 2025-05-07 09:18:40,913 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720907.000000
Line  1697: 2025-05-07 09:18:40,921 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720915.000000
Line  1702: 2025-05-07 09:18:40,932 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720916.000000
Line  1722: 2025-05-07 09:18:40,940 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720935.000000
Line  1727: 2025-05-07 09:18:40,942 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720935.000000
Line  1747: 2025-05-07 09:18:40,948 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720944.000000
Line  1752: 2025-05-07 09:18:40,950 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720944.000000
Line  1772: 2025-05-07 09:18:40,957 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720952.000000
Line  1777: 2025-05-07 09:18:40,959 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720952.000000
Line  1797: 2025-05-07 09:18:40,965 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720961.000000
Line  1802: 2025-05-07 09:18:40,967 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720961.000000
Line  1822: 2025-05-07 09:18:40,973 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720969.000000
Line  1827: 2025-05-07 09:18:40,979 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720969.000000
Line  1847: 2025-05-07 09:18:40,985 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t1  1746580720981.000000
Line  1852: 2025-05-07 09:18:40,986 INFO     [stdout_thd] [command.py@116 printOutput] 326944 [ec78]     [AEC::Process] t2  1746580720982.000000

And here is the compiler flags set

set(WASM_AEC_FLAGS -O3 -g0 -s MODULARIZE=1 -s DYNAMIC_EXECUTION=0 -s EXPORT_NAME="createModule" -s EXPORTED_FUNCTIONS=['_malloc','_free'] -s INITIAL_MEMORY=18MB -s BINARYEN_ASYNC_COMPILATION=0 -s ENVIRONMENT=node)

Thanks.

purplesnail · 2025-05-07T01:33:48Z

I checked the generated JS, and noticed the same code with yours
var _emscripten_get_now=()=>performance.now();

I can get correct float values with the same C++ code with 3.1.22 and Node16

Line  2591: 2025-05-07 09:40:06,287 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770789.283516
Line  2596: 2025-05-07 09:40:06,290 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770789.550604
Line  2601: 2025-05-07 09:40:06,294 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770820.661719
Line  2606: 2025-05-07 09:40:06,296 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770821.325450
Line  2611: 2025-05-07 09:40:06,300 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770826.225379
Line  2616: 2025-05-07 09:40:06,302 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770826.419981
Line  2621: 2025-05-07 09:40:06,304 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770831.230202
Line  2626: 2025-05-07 09:40:06,306 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770831.418105
Line  2631: 2025-05-07 09:40:06,309 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770835.323758
Line  2636: 2025-05-07 09:40:06,310 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770835.481691
Line  2641: 2025-05-07 09:40:06,319 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770845.295241
Line  2646: 2025-05-07 09:40:06,320 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770845.437874
Line  2651: 2025-05-07 09:40:06,322 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770849.478657
Line  2656: 2025-05-07 09:40:06,324 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770849.617244
Line  2661: 2025-05-07 09:40:06,326 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t1  48770853.196290
Line  2666: 2025-05-07 09:40:06,327 INFO     [stdout_thd] [command.py@116 printOutput] 338711 [a148]     [AEC::Process] t2  48770853.329157

sbc100 · 2025-05-07T05:05:38Z

The fact that you are seeing no decimal places is very odd. If you simply run node -e "console.log(performance.now())" you can see that performance.now() reports number that include decimal places:

$ node -e "console.log(performance.now())"
73.704157

Something strange must be going on with how the result of emscripten_get_now is being used. The numbers you are seeing such as 1746580720952.000000 also look add because they are so large. Unless you program has been running for hours I would not expect to see such values since performance.now() seems to report milliseconds since startup.

How are you printing the values? Can you run the above tiny program to confirm that you see the same types of values that I do?

purplesnail · 2025-05-07T06:25:25Z

It's correct when I run your tiny program, but I noticed the NodeJS version is 22, which is different from my project.
Maybe it's related to the NodeJs version?

purplesnail · 2025-05-07T06:44:58Z

I've tested node18, node20 and node22 with the tiny program. All of them work fine.
So it seems related to the compiler flags with my real project?

sbc100 · 2025-05-07T17:23:45Z

Could you share the full set of link flag you use in your larger program.

Also are you actually using printf, or something else to print the time?

purplesnail · 2025-05-08T02:20:19Z

I have a performance polyfill like below:

if (!performance)  {
    var performance = {
        now() { return Date.now(); }
    };
}

In Node.js 16, the performance object was automatically exposed in the module scope. So performance is defined and Date.now() will not executed and emscripten_get_now() returns a float value with high precision.

However, Node.js 20 enforces stricter module encapsulation. With the above code, performance is not defined and Date.now() will be executed and emscripten_get_now() returns low precision value.

After I use if (typeof globalThis.performance === 'undefined') to check if performance is defined, the issue has been resolved.

Thank you very much @sbc100

purplesnail closed this as completed May 8, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Can I get high precision timing with EMSDK 4.0.5? #24267

Can I get high precision timing with EMSDK 4.0.5? #24267

purplesnail commented May 6, 2025

sbc100 commented May 6, 2025

sbc100 commented May 6, 2025

purplesnail commented May 7, 2025 •

edited

Loading

purplesnail commented May 7, 2025 •

edited

Loading

sbc100 commented May 7, 2025

purplesnail commented May 7, 2025

purplesnail commented May 7, 2025 •

edited

Loading

sbc100 commented May 7, 2025

purplesnail commented May 8, 2025

Can I get high precision timing with EMSDK 4.0.5? #24267

Can I get high precision timing with EMSDK 4.0.5? #24267

Comments

purplesnail commented May 6, 2025

sbc100 commented May 6, 2025

sbc100 commented May 6, 2025

purplesnail commented May 7, 2025 • edited Loading

purplesnail commented May 7, 2025 • edited Loading

sbc100 commented May 7, 2025

purplesnail commented May 7, 2025

purplesnail commented May 7, 2025 • edited Loading

sbc100 commented May 7, 2025

purplesnail commented May 8, 2025

purplesnail commented May 7, 2025 •

edited

Loading

purplesnail commented May 7, 2025 •

edited

Loading

purplesnail commented May 7, 2025 •

edited

Loading