Tracy-based expr evaluation profiler #9967

picnoir · 2024-02-08T09:09:14Z

This is a WIP profiler for the Nix code itself, not the cpp Nix evaluator. The goal is to provide some tooling to improve the Nixpkgs evaluation performance.

This is a WIP Nix profiler using Tracy. The idea is to trace the evaluation of the expression atoms to figure out what is expensive. We are roughly tracing the thunk evaluation. Nix is a lazy language, I think this is what makes most sense.

Short demo video

TODO before Undrafting

This is not ready yet. We need to fix at least those two issues before undrafting this PR.

HELP WELCOME :)

Elephant in the room: tracy SEGFAULTS!!!!!!!!!

We have those weird "???" frames in Tracy. Hovering them with the mouse segfault the viewer.

Removing the line and the column in the position pretty printer makes them go away. Sadly, removing the column and position from the trace also makes the profiler useless :D

There's something very wrong in our client code, but I couldn't figure out what. For now. This is the first item on my TODO list.

Profiler performance

There's room for improvement. Random datapoint, with the profiler enabled:

[nix-shell:~/code-root/github.com/NixOS/nix]$ time ./outputs/out/bin/nix-instantiate -A nixosTests.pleroma ../nixpkgs
warning: you did not specify '--add-root'; the result might be removed by the garbage collector
/nix/store/z6nqb4zkx59hqn00rpzpzq4fcp34y9pa-vm-test-run-pleroma.drv

real    1m41,835s
user    2m51,728s
sys     0m11,388s

Without the profiler:

[nix-shell:~/code-root/github.com/NixOS/nix]$ time nix-instantiate -A nixosTests.pleroma ../nixpkgs
warning: you did not specify '--add-root'; the result might be removed by the garbage collector
/nix/store/z6nqb4zkx59hqn00rpzpzq4fcp34y9pa-vm-test-run-pleroma.drv

real    0m12,478s
user    0m9,998s
sys     0m1,431s

That's not a surprise, I did not make any effort here, each profiler macro is generating at least 3 allocations.

We should run perf on this and see what's wrong.

Move out the trace macros from the eval call sites

See #9967 (comment)

Is this useful/refine design?

We should spend some time using this profiler. Can we spot issues with it? Can we remove some useless noise from the traces?

There's no magic trick here, we need to spend time using the tool to improve it.

How to test?

nix build github:picnoir/nix/pic/tracy-profiler
Open tracy. nix-shell -p tracy. Then, either lauch the graphical profiler to watch the capture in real time (tracy), either record the run through the headless capture utility (capture -o capture.tracy).
Evaluate something with the nix-instantiate utility you built in step 2. EG. ./result/bin/nix-instantiate -A nixosTests.pleroma path-to/nixpkgs/
Enjoy the operation game, avoid the ??? with your mouse to prevent segfaults. Scroll-wheel to zoom/unzoom, left click to move the trace.

Priorities and Process

Add 👍 to pull requests you find important.

The Nix maintainer team uses a GitHub project board to schedule and track reviews.

This is a first quick-and-dirty way to get the tracy integration up and running without losing my sanity trying to bend the autotools setup to work with it. Introducing a tracy submodule, injecting the required headers from here, building the TracyClient.cpp file to get the actual tracy client library.

We're leveraging the ZoneTransientN macro to send dynamic strings containing the expression type, file and position in that file of the expression Nix is currently evaluating. We had to add a new showExprType method to the Expr class to get a const string containing the name of an expression.

Two expressions evaluations seem to be contained in the EvalState class. Tracing them as well through a new macro.

Tracing the primops with Tracy as well. Not sure it really worth the overhead, but we still can revisit this decision later if we realize primops are not that important perf-wise.

pennae · 2024-02-08T09:24:16Z

please don't add even more junk to each individual expr ::eval. tracing is a rare operation, if anything this should be done as a AST wrapper that inserts tracer nodes on every Expr* edge.

picnoir · 2024-02-08T09:36:00Z

The idea is to hide the profiler behind a autotools feature flag making these macros no-op. I won't undraft this until the runtime cost of it when the feature flag is disabled is 0.

please don't add even more junk to each individual expr ::eval. tracing is a rare operation, if anything this should be done as a AST wrapper that inserts tracer nodes on every Expr* edge.

Performance-aside, this sounds like a better approach. Would you have any link (code, documentation) that would set me on track to do this?

pennae · 2024-02-08T09:41:36Z

Performance-aside, this sounds like a better approach. Would you have any link (code, documentation) that would set me on track to do this?

have a look at the bindVars set of methods. a wrapForTracing set that runs after bindVars when requested and a new synthetic ast node that only does tracer bookkeeping should work just fine.

Well, this was as painful as expected. Introducing a proper autotool-based tracy build. I don't think this is the right approach, but hey, it works. Tracy is not distributing any pkg-config file, so we had to fallback to a more "manual" method to propagate the headers path. Instead of having a plain enable/disable flag, we send the path to the tracy /public subfolder (~= $out in the Tracy Nix derivation). The flake Nixpkgs is currently pointing to 23.05. The tracy derivation was only building the visualizer, not the client library back then. We introduce a 23.11 Nixpkgs and build its Tracy derivation with the 23.05 toolchain to go around some glibc ABI incompatibilities. Kudos to Mic92 for the help for the flake bit. Co-authored-by: Jörg Thalheim <[email protected]>

nixos-discourse · 2024-02-29T07:20:29Z

This pull request has been mentioned on NixOS Discourse. There might be relevant details there:

https://discourse.nixos.org/t/2024-02-28-nix-team-meeting-129/40499/1

picnoir · 2024-02-29T08:01:35Z

Small status update:

Here's a tracy dirty hack to workaround the segfaults: wolfpld/tracy@c9addab

My current plan is to spend some time using the tool to see if it's worthwhile. If it is, I'll spend more time debugging this tracy race condition and improve the integration to the Nix codebase.

No ETA, $work has been pretty intense for the last 2 weeks, I do this on my sparetime.

nixos-discourse · 2024-03-12T14:02:58Z

This pull request has been mentioned on NixOS Discourse. There might be relevant details there:

https://discourse.nixos.org/t/nix-flamegraph-or-profiling-tool/33333/14

Atemu · 2024-06-29T22:23:06Z

The tracy patch does not appear to fix the segfault for me, it still crashes when I dare to move my cursor over its window.

I've opened a trace of a NixOS eval and am on a relatively recent nixos-unstable.

picnoir · 2024-07-01T13:48:59Z

Hmm, I may be able to help if you can post the stacktrace.

Atemu · 2024-07-01T21:20:59Z

coredumpctl info

           PID: 517456 (tracy)
           UID: 1000 (atemu)
           GID: 100 (users)
        Signal: 11 (SEGV)
     Timestamp: Sun 2024-06-30 00:19:58 CEST (1 day 22h ago)
  Command Line: tracy /tmp/capture.tracy
    Executable: /nix/store/fmj04aacbnh17dw8anc58i7c3lnv0w18-tracy-0.10/bin/tracy
 Control Group: /user.slice/user-1000.slice/session-5.scope
          Unit: session-5.scope
         Slice: user-1000.slice
       Session: 5
     Owner UID: 1000 (atemu)
       Boot ID: e58948e699d44d2fa64381c8261327ca
    Machine ID: 165e455633b044ceaa6af31d38811ced
      Hostname: THESEUS
       Storage: /var/lib/systemd/coredump/core.tracy.1000.e58948e699d44d2fa64381c8261327ca.517456.1719699598000000.zst (present)
  Size on Disk: 443.1M
       Message: Process 517456 (tracy) of user 1000 dumped core.
                
                Module libtbbmalloc.so.2 without build-id.
                Module libXext.so.6 without build-id.
                Module libX11.so.6 without build-id.
                Module libGLX.so.0 without build-id.
                Module libGL.so.1 without build-id.
                Module libpciaccess.so.0 without build-id.
                Module liblzma.so.5 without build-id.
                Module libxml2.so.2 without build-id.
                Module libncursesw.so.6 without build-id.
                Module libdrm_intel.so.1 without build-id.
                Module libdrm_amdgpu.so.1 without build-id.
                Module libdrm_radeon.so.1 without build-id.
                Module libsensors.so.5 without build-id.
                Module libzstd.so.1 without build-id.
                Module libXdmcp.so.6 without build-id.
                Module libXau.so.6 without build-id.
                Module libxshmfence.so.1 without build-id.
                Module libxcb-sync.so.1 without build-id.
                Module libxcb-present.so.0 without build-id.
                Module libxcb-dri3.so.0 without build-id.
                Module libdrm.so.2 without build-id.
                Module libxcb-xfixes.so.0 without build-id.
                Module libxcb-randr.so.0 without build-id.
                Module libxcb-dri2.so.0 without build-id.
                Module libxcb.so.1 without build-id.
                Module libX11-xcb.so.1 without build-id.
                Module libexpat.so.1 without build-id.
                Module libcap.so.2 without build-id.
                Module libbrotlicommon.so.1 without build-id.
                Module libGLdispatch.so.0 without build-id.
                Module libffi.so.8 without build-id.
                Module libbrotlidec.so.1 without build-id.
                Module libpng16.so.16 without build-id.
                Module libbz2.so.1 without build-id.
                Module libz.so.1 without build-id.
                Module libgcc_s.so.1 without build-id.
                Module libstdc++.so.6 without build-id.
                Module libtbb.so.2 without build-id.
                Module libxkbcommon.so.0 without build-id.
                Module libEGL.so.1 without build-id.
                Module libcapstone.so.5 without build-id.
                Module libfreetype.so.6 without build-id.
                Module tracy without build-id.
                Stack trace of thread 517456:
                #0  0x00000000005b53f9 n/a (tracy + 0x1b53f9)
                #1  0x00000000005d80e7 n/a (tracy + 0x1d80e7)
                #2  0x00000000004c3df2 n/a (tracy + 0xc3df2)
                #3  0x00000000004bdbca n/a (tracy + 0xbdbca)
                #4  0x000000000059cae4 n/a (tracy + 0x19cae4)
                #5  0x00000000004e1ace n/a (tracy + 0xe1ace)
                #6  0x00000000004e4b40 n/a (tracy + 0xe4b40)
                #7  0x0000000000654d5c n/a (tracy + 0x254d5c)
                #8  0x0000000000417254 n/a (tracy + 0x17254)
                #9  0x00007fde13c3c10e __libc_start_call_main (libc.so.6 + 0x2a10e)
                #10 0x00007fde13c3c1c9 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x2a1c9)
                #11 0x00000000004183f5 n/a (tracy + 0x183f5)
                
                Stack trace of thread 517457:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x0000000000651c3c n/a (tracy + 0x251c3c)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517462:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517461:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517463:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517464:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517468:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517471:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517465:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517472:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517473:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517474:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517469:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517467:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517475:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517477:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517498:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517493:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517488:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517478:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517480:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517476:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517479:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517485:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517497:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517483:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517491:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517495:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517489:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00000000004aaeb7 n/a (tracy + 0xaaeb7)
                #3  0x00007fde13ee86d3 execute_native_thread_routine (libstdc++.so.6 + 0xe86d3)
                #4  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #5  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517484:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517482:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517481:
                #0  0x00007fde13d19d1d syscall (libc.so.6 + 0x107d1d)
                #1  0x00007fde141da655 _ZN3tbb8internal3rml14private_worker3runEv (libtbb.so.2 + 0x20655)
                #2  0x00007fde141da699 _ZN3tbb8internal3rml14private_worker14thread_routineEPv (libtbb.so.2 + 0x20699)
                #3  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #4  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                
                Stack trace of thread 517466:
                #0  0x00007fde13c9cc5e __futex_abstimed_wait_common (libc.so.6 + 0x8ac5e)
                #1  0x00007fde13c9f4c0 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x8d4c0)
                #2  0x00007fddf9d1dc49 cnd_wait (radeonsi_dri.so + 0x11dc49)
                #3  0x00007fddf9cfe04b util_queue_thread_func (radeonsi_dri.so + 0xfe04b)
                #4  0x00007fddf9d1db87 impl_thrd_routine (radeonsi_dri.so + 0x11db87)
                #5  0x00007fde13ca0272 start_thread (libc.so.6 + 0x8e272)
                #6  0x00007fde13d1bdec __clone3 (libc.so.6 + 0x109dec)
                ELF object binary architecture: AMD x86-64

picnoir added 4 commits February 8, 2024 09:21

Tracing EvalState members

b35cc13

Two expressions evaluations seem to be contained in the EvalState class. Tracing them as well through a new macro.

Tracing primops

376d9dd

Tracing the primops with Tracy as well. Not sure it really worth the overhead, but we still can revisit this decision later if we realize primops are not that important perf-wise.

picnoir force-pushed the pic/tracy-profiler branch from 671739c to 3ea4870 Compare February 8, 2024 09:44

Mic92 mentioned this pull request Jun 18, 2024

Nixpkgs eval time is increasing too fast NixOS/nixpkgs#320528

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tracy-based expr evaluation profiler #9967

Tracy-based expr evaluation profiler #9967

picnoir commented Feb 8, 2024 •

edited

Loading

pennae commented Feb 8, 2024

picnoir commented Feb 8, 2024 •

edited

Loading

pennae commented Feb 8, 2024

nixos-discourse commented Feb 29, 2024

picnoir commented Feb 29, 2024

nixos-discourse commented Mar 12, 2024

Atemu commented Jun 29, 2024

picnoir commented Jul 1, 2024 via email

Atemu commented Jul 1, 2024

Tracy-based expr evaluation profiler #9967

Are you sure you want to change the base?

Tracy-based expr evaluation profiler #9967

Conversation

picnoir commented Feb 8, 2024 • edited Loading

TODO before Undrafting

Elephant in the room: tracy SEGFAULTS!!!!!!!!!

Profiler performance

Move out the trace macros from the eval call sites

Is this useful/refine design?

How to test?

Priorities and Process

pennae commented Feb 8, 2024

picnoir commented Feb 8, 2024 • edited Loading

pennae commented Feb 8, 2024

nixos-discourse commented Feb 29, 2024

picnoir commented Feb 29, 2024

nixos-discourse commented Mar 12, 2024

Atemu commented Jun 29, 2024

picnoir commented Jul 1, 2024 via email

Atemu commented Jul 1, 2024

picnoir commented Feb 8, 2024 •

edited

Loading

picnoir commented Feb 8, 2024 •

edited

Loading