• Scott Lystig Fritchie
• Senior Software Engineer at Basho Japan KK
• Email: <scott@basho.com>
• Twitter: @slfritchie
• UNIX, Erlang and me:
  • UNIX sysadmin & programmer since 1986
  • Erlang programmer since 2000
  • Publications by USENIX and the ACM
  • Speaker at Erlang User Conference and Erlang Factory

• Today's presentation: http://twitter.com/slfritchie
  • Long term: http://www.snookles.com/erlang/ef2015/
• Today's flame graphs: https://github.com/slfritchie/eflame
• Today's Erlang hacks: https://github.com/slfritchie/otp
• Flame graph home: https://github.com/brendangregg/FlameGraph
  • General introduction: http://www.brendangregg.com/flamegraphs.html

• You have identified code to profile, based on "USE Method" or other measurement-based methodology.
  • Examine a specific module
  • Examine a specific subsystem/OTP application
  • Not sure where to start: examine an entire system under a specific workload.
• Guesses are wrong 127% of the time.
• Be skeptical: doubt your measurements, verify them!
  • Multiple methods
  • Experiment while your test is running!
• Beard definitely not required!

• Identify the Erlang function(s) that is consuming the most CPU resource.
  • Either wall-clock time or "on scheduler" time
  • Depends on the measurement method

• Most advice about benchmarking is also valid advice for profiling.
• source: https:

//pbs.twimg.com/profile_images/512451438572613632/3T6mju_J.jpeg, http: //www.brendangregg.com/Images/systemsperf_cover_123.jpeg

1. Pick a benchmark tool.
2. Run it with a variety of options.
3. Make a slide deck of the results.
4. Hand the slides to management.

• You benchmark A,
• but actually measure B,
• and conclude you've measured C

.

"You analyze performance while the benchmark is running – not just after it's done – using other tools."

Why? Confirm that you really understand:

1. What does the test actually do?
2. How the system under test actually respond to the test?
3. What are the true limiters of the system under test?
4. What are the true limiters of the test itself?

.

"You analyze performance while the system is running – not just after it's done – using other tools."

Why? Confirm that you really understand:

1. What does the workload actually do?
2. How the code under test actually respond to the workload?
3. What are the true limiters of the code under test?
4. What are the true limiters of the profiler tool itself?

sources: https://vimeo.com/99011731, http://www.erlang-factory.com/euc2014/roberto-aloi, http://www.erlang-factory.com/euc2014/martin-kjellin

• Measure, don't guess.
• Trust your measurements.
• Measure before optimizing.
• Know what you're measuring.

"[Profiling is] Inherently difficult, you have to be aware of the entire stack."

sources: https://www.erlang-solutions.com/resources/webinars/understanding-erlang-scheduler (about minute 31), http://www.erlang-factory.com/euc2014/lukas-larsson

• You need to understand the major components of the system:
  • How OS threads are used by Erlang schedulers, async I/O pool, etc.
  • Memory management: allocation, garbage collection, VM allocators, …
  • Types of Erlang processes & what they do.
  • Message passing patterns: send/receive within a node? across nodes? Mailbox sizes
  • Erlang file I/O doesn't work like most other languages'
    • Message passing <-> file port driver!
    • Support for "diskless" mode is still there!
  • Data shared by ETS tables really isn't shared: it's copied on-demand in & out of ETS tables <-> Erlang process heaps
    • Except for "large" Erlang binary terms! ^_^

1. Measure these three things:
   • Utilization (% busy/utilized)
   • Saturation rates (items queued due to 100% utilization)
   • Errors
2. Find largest source of errors, or saturation, or utilization
3. Re-focus USE method on that thing you found.
4. Perhaps fix that bottleneck. Go to #1 if not fast enough.
5. http://dtrace.org/blogs/brendan/2012/02/29/the-use-method/

• OS level
  • memory usage, disk I/O & I/O wait, CPU usage, network usage,…
• Erlang
  • elapsed wall clock time, message queues, reductions executed, garbage collection events, process scheduler events, …

• Not enough time to talk about them all!
• Use your favorite Web search tool to find more info about them.
• Afterward, I'll focus on flame graphs

• cprof and epof and fprof
• etop and pman and observer
• ttb
• percept and percept2 (http://www.erlang-factory.com/upload/presentations/808/Percept2.pdf)
• instrument
• lcnt
• "Efficiency Guide User's Guide" in OTP docs

• https://github.com/massemanet/eper package: redbug and dtop
• https://github.com/ferd/recon package and his "Stuff Goes Bad: Erlang in Anger" ebook
• riak_sysmon & cluster_info @ https://github.com/basho/
• https://github.com/virtan/eep + kcachegrind
• https://github.com/isacssouza/erlgrind

• Erlang VM internals:
  • gprof, Valgrind, other C/assembly profilers, DTrace/SystemTap
• Don't forget OS tools!
  • top, htop, sar, iostat, vmstat, strace, sysdig, …

• timer:tc/1, /2, /3
  • Beware! CLI code is interpreted differently than compiled code!
• latency_histogram_tracer.erl
  • Create detailed histogram stats on latencies of Mod:Fun/Arity calls.
  • https://gist.github.com/slfritchie/159a8ce1f49fc03c77c6
  • Requires folsom package for histograms
• Adding dynamic tracing probes for DTrace/SystemTap measurements.
  • For example, dyntrace:pn(25,1) and dyntrace:pn(25,2) additions to your code.
  • Measure latencies with a D script between erlang$pid::user_probe-n25 probes with arg=1 vs. arg=2
  • Requires dyntrace support compiled into your VM

• You turned it off, didn't you?

• It's simple. And it's complex. It's both!
• For each event, send a message to a single "event tracer" process/port.
  • The consumer/destination/sink for trace messages

• Any Erlang process
• Any Erlang port
• The scheduler threads

• Any 1/N/all processes running right now
• Any processes spawned after tracing starts
• Any processes linked after tracing starts

• Calling a function (global or local)
  • filter based on:
    • module name
    • function name
    • # of arguments
    • Erlang-style pattern matching on func's argument list!
• Sending/receiving a message
• Process is starting/stopping GC
• Process is running/stopped by scheduler thread
• Process has exited

• Turn on and off anytime
  • On developer's laptop
  • On production system!
• The API is odd, but the pattern matching is powerful
• "Event tracer"/consumer can execute any Erlang code
  • Turing complete, very flexible

• Turn on and off anytime
  • On production system! And forget to turn it off.
• The API is frequently difficult to remember
  • That's the reason for so many tools to manage the low-level tracing API
• Only 1 event tracer per VM
  • Easy to create "event tsunami" of millions of event messages
    • Killing entire VMs in production = not fun
  • TCP and file port tracers have lower overhead but not low enough
  • Capacity limit: 1 tracer = 1 CPU core of work available

• API is mostly easy-to-use
• Measure wall-clock execution time of {Mod, Func, ArgList}
• Easy to measure pure function {Mod, Func, ArgList} time!
• Aware of call stacks:
  • Time executed by function F
  • Time executed by functions called by function F
• Implemented by Erlang tracing
  • Use it in production, if you wish….

• Report format requires some practice to read correctly
  • erlgrind and eep have better (?) visualization tools
• Not designed for multi-process measurements
  • Call stack interpretation can be ok or terrible
• Implemented by Erlang tracing
  • High overhead: 1 message per function call or return
  • Only 1 consumer process/port
  • Can slow down a Riak system by 2-3 orders of magnitude!

Source: https://twitter.com/mranney/status/578056023841230848

• Invented by Sun Microsystems alumni as an alternative way of visualizing profiling data with call stacks.
• Originally based DTrace + Solaris
• Very quickly ported to many other platforms
• Links:
  • http://www.brendangregg.com/flamegraphs.html
  • https://github.com/brendangregg/FlameGraph

Source: www.snookles.com/scotttmp/eflame2/riak.1.svg

• Y axis: call stack depth
• X axis: proportion of # of samples (or perhaps relative execution time)
  • Left-to-right order is alphabetical
  • Left-to-right order has nothing to do with passage of time

• Y axis: call stack depth
• X axis: proportion of # of samples (or perhaps relative execution time)
  • Left-to-right order is alphabetical
  • Left-to-right order has nothing to do with passage of time

• Method 1: profile the VM itself using standard profiling techniques + Gregg's flame graph toolkit
  • Good view into the VM's internal implementation
  • Not good view into Erlang code behavior
• Method 2: Vlad Ki's eflame library
  • https://github.com/proger/eflame
  • Uses Erlang tracing (all strengths & weaknesses)
  • Not always accurate call stack reporting
• Method 3: Scott Lystig Fritchie's eflame2 library
  • https://github.com/slfritchie/eflame
  • Uses alternate call stack calculation
  • Can use Erlang tracing (all strengths & weaknesses)
  • Can use patched Erlang VM for much lower overhead cost
  • Easier-to-use API, perhaps, I hope?
  • Not always accurate call stack reporting

1. Start workload on system. (And keep it running!)
2. Trigger measurement framework (previous slide)
3. Convert raw measurement format to standard flame graph file format.
4. Generate flame graph's native SVG format.
5. Convert SVG to other formats.
   • Not all Web browsers have native SVG support yet {sigh}

1. git clone https://github.com/slfritchie/eflame.git
2. cd eflame
3. make
4. Copy the ebin/eflame2.beam file to /tmp on whatever machine it is that you wish to use to generate a flame graph. (Call it the System Under Test or SUT.)
5. Run code:add_pathz("/tmp"). at the Erlang CLI on the SUT.

1. Start the workload on the SUT.
2. Collect some traces:
   • For example, to gather trace events on all processes and all newly-spawned processes for all global function calls for 10 seconds (10,000 milliseconds).
   • Run eflame2:write_trace( global_calls_plus_new_procs, "/tmp/ef.test.0", all, 10*1000).

1. Convert the binary trace to an ASCII trace:
   • Run eflame2:format_trace("/tmp/ef.test.0", "/tmp/ef.test.0.out").
2. Convert the ASCII trace to an SVG flame graph image:
   • Run at a BASH/C Shell/login shell:
     • cat /tmp/ef.test.0.out | flamegraph.riak-color.pl > output.svg

• Use little-documented [process_dump] match spec action.
  • e.g., MatchSpec = [{'_',[],[{message,{process_dump}}]}]
• Create same process summary text that's used for Erlang erl_core.dump files at crash time!
• On a Riak system, each trace message can be 15 KBytes or more!
• Parse the Erlang function call info (and throw the rest away).

• Patch the Erlang VM to provide an alternate method of generating a call stack report, without all of the extra/unwanted reporting stuff that the process_dump match spec.
• Added process_backtrace match spec to write stack trace only
• Much faster, much smaller trace messages.
• Use eflame2:write_trace_exp/4 or eflame2:write_trace_exp/6 to use the process_backtrace style trace generation.

• A Riak system, tracing all processes, can slow down 50x-300x!
• Time-based sampling, like gprof or DTrace use, have very low overhead and can (given enough time) generate statistically valid profiles.
• But neither gprof nor DTrace can understand Erlang process stacks
  • View the VM's C internals and not individual Erlang process state
  • If you are a DTrace magician, please contact me!

1. git clone https://github.com/slfritchie/otp.git
2. cd otp
3. git checkout slf-profiling-tracing-hack1-v16
4. ./otp_build autoconf
5. ./configure --all-your-favorite-build-flags...
6. make && make install

• Add new async thread that does nothing but:
  • Sleep periodically
  • Check global vars after waking up
  • If global vars say "yes", set flags in each scheduler thread's Process structure to ask for a tracing sample.

• For each OpCase opcode inside of process_main()
  • Add a check to see if a time-based sample should be dumped now.
  • Added new field in Process structure.
  • If yes, write trace info directly to a file via fwrite(3)

#define GOOFUS_CHECK 
    if (ERTS_GET_SCHEDULER_DATA_FROM_PROC(c_p)     \
                              ->goofus_count != 0) \
        goofus_write_time_sample(c_p)

• Add GOOFUS_CHECK to lots of places….

• Add extra (ugly) statements to each opcode's implementation
  • Could hide ugliness with even more macros! ^_^
• Cannot "see" activity such as GC or port deferred work
• Cannot "see" async file I/O activity directly
• Might add bias toward functions immediately after schedule in by scheduler? (Needs more investigation)
• Very low overhead, even when sampling every few milliseconds
• Appears to be more accurate (most of the time) than per-function trace events.

1. Clone & compile & install the Erlang/OTP repo described above.
2. Start a workload on the SUT to be observed.
3. Run the following at the Erlang shell:

1. Convert the trace file to flame-graph-ready input and then to an SVG flame graph.

/path/to/runtime_tools/priv/parse_goofus.pl \
    < /tmp/goofus.PID.out | sort | uniq -c | \
    awk '{ print $2, " ", $1}' | \
    flamegraph.riak-color.pl > /tmp/flame-graph.svg

See https://github.com/slfritchie/eflame/blob/feature/alt-stack-method/README-Riak-Example.md for text and tutorial ideas here.

• Don't assume function X is being called: confirm it
• Don't assume function X is fast: confirm it
  • These measurement techniques have flaws
  • Confirmation from multiple techniques builds confidence