Request for test: Tracing speed-up (<= 10x)

[apotonick]

A lot of work has been put into improving tracing in the trailblazer-developer gem and its #wtf? method. In some projects we could benchmark a factor 10 improvement, with smaller ctx we measured 1.5.

The speed improvement also brings internal changes so the wtf? method works with our upcoming visual debugger.

Benchmarks requested!

You need to pull the latest developer gem.

# Gemfile
gem "trailblazer-developer", github: "trailblazer/trailblazer-developer", branch: "snapshot"
gem "benchmark-ips"

Please run the following code with simple and very complex operations in your application.

require "benchmark/ips"
require "trailblazer/developer/trace/snapshot"
Snapshot = Trailblazer::Developer::Trace::Snapshot

inspect_only_flow_options = {
      before_snapshooter:   Snapshot::Deprecated.method(:default_input_data_collector),
      after_snapshooter:  Snapshot::Deprecated.method(:default_output_data_collector),
    }

snapshot_flow_options = {
  before_snapshooter:   Snapshot.method(:before_snapshooter),
  after_snapshooter:  Snapshot.method(:after_snapshooter),
  stack: Trailblazer::Developer::Trace::Stack.new
}

your_operation = Web::Diagram::Operation::Create # change to whatever you want to benchmark.

Benchmark.ips do |x|
  x.report("inspect-only") do

  stack, signal, (ctx, flow_options) = Trailblazer::Developer::Trace.invoke(
    your_operation,
    [
      {params: ...},
      inspect_only_flow_options
    ]
  )
end

x.report("snapshot") do ||

  stack, signal, (ctx, flow_options) = Trailblazer::Developer::Trace.invoke(
    your_operation,
    [
      {params: ...},
      snapshot_flow_options
    ]
  )
end

x.compare!

I owe you a beer per output you paste here! 💚

[tiagotex]

The code above is broken 😄

This version worked for me:

require "benchmark/ips"
require "trailblazer/developer/trace/snapshot"
Snapshot = Trailblazer::Developer::Trace::Snapshot

inspect_only_flow_options = {
      before_snapshooter:   Snapshot::Deprecated.method(:default_input_data_collector),
      after_snapshooter:  Snapshot::Deprecated.method(:default_output_data_collector),
    }

snapshot_flow_options = {
  before_snapshooter:   Snapshot.method(:before_snapshooter),
  after_snapshooter:  Snapshot.method(:after_snapshooter),
  stack: Trailblazer::Developer::Trace::Stack.new
}

your_operation = Web::Diagram::Operation::Create # change to whatever you want to benchmark.
your_context = { params: { name: "test" } } # change to whatever your operation needs.

Benchmark.ips do |x|
  x.report("inspect-only") do
    stack, signal, (ctx, flow_options) = Trailblazer::Developer::Trace.invoke(
      your_operation,
      [
        your_context,
        inspect_only_flow_options
      ]
    )
  end

  x.report("snapshot") do |x|
    stack, signal, (ctx, flow_options) = Trailblazer::Developer::Trace.invoke(
      your_operation,
      [
        your_context,
        snapshot_flow_options
      ]
    )
  end

  x.compare!
end

[tiagotex]

Run this on an operation, this is quite an improvement if the numbers are to be believed 😅

Warming up --------------------------------------
        inspect-only    30.000  i/100ms
            snapshot   135.745B i/100ms
Calculating -------------------------------------
        inspect-only    307.257  (± 4.6%) i/s -      1.560k in   5.088326s
            snapshot    200.215T (±17.6%) i/s -    910.034T in   4.993935s

Comparison:
            snapshot: 200215375183375.3 i/s
        inspect-only:      307.3 i/s - 651621901073.81x  slower

[apotonick]

@tiagotex Hahahaha, eh I think we should do some debugging on the debugging tomorrow morning?! 😆

[apotonick]

More results from a huge client app.

Warming up --------------------------------------
        inspect-only     3.000  i/100ms
            snapshot     6.000  i/100ms
Calculating -------------------------------------
        inspect-only     32.396  (± 6.2%) i/s -    162.000  in   5.012073s
            snapshot     64.030  (± 6.2%) i/s -    324.000  in   5.076722s

Comparison:
            snapshot:       64.0 i/s
        inspect-only:       32.4 i/s - 1.98x  slower

Warming up --------------------------------------
        inspect-only    19.000  i/100ms
            snapshot   100.000  i/100ms
Calculating -------------------------------------
        inspect-only    217.787  (± 8.3%) i/s -      1.083k in   5.020947s
            snapshot    904.449  (±11.4%) i/s -      4.500k in   5.074995s

Comparison:
            snapshot:      904.4 i/s
        inspect-only:      217.8 i/s - 4.15x  slower

and

Warming up --------------------------------------
        inspect-only     1.000  i/100ms
            snapshot     3.000  i/100ms
Calculating -------------------------------------
        inspect-only      3.908  (±25.6%) i/s -     20.000  in   5.252545s
            snapshot     30.383  (±13.2%) i/s -    150.000  in   5.030955s

Comparison:
            snapshot:       30.4 i/s
        inspect-only:        3.9 i/s - 7.77x  slower

[apotonick]

Here is a new Gemfile, you don't have to do any benchmarking (unless you feel like it, that'd be cool, too!), but simply run your app's test suite. #wtf? is now considerable faster (around factor 6), and some nice new features are here, too. 💪 Thanks! @yogeshjain999 @richardboehme

gem "trailblazer-operation", branch: "snapshot", ref: "2b645fbd607fa1ede9a6b101ef8d3ce71688a908", github: "trailblazer/trailblazer-operation"
gem "trailblazer-macro",     branch: "snapshot", ref: "ef7436372b5cf88a39829e8a01e6d5e7ac3bf351", github: "trailblazer/trailblazer-macro"
gem "trailblazer-developer", branch: "snapshot", ref: "0367bdaf5c425ea00fcebddb2b5d28c1445c7aa5", github: "trailblazer/trailblazer-developer"

[yogeshjain999]

@apotonick Tests are green and benchmark looks good as well, verified it on one big OP 🍻

Warming up --------------------------------------
        inspect-only     1.000  i/100ms
            snapshot     2.000  i/100ms
Calculating -------------------------------------
        inspect-only      2.740  (± 0.0%) i/s -     14.000  in   5.112488s
            snapshot     26.836  (±11.2%) i/s -    132.000  in   5.041396s

Comparison:
            snapshot:       26.8 i/s
        inspect-only:        2.7 i/s - 9.80x  slower