Trace GC and Scheduler

spec/compiler/crystal/tools/tracing_spec.cr

@@ -0,0 +1,104 @@
+require "spec"
+require "compiler/crystal/tools/tracing"
+require "../../../support/tempfile"
+
+describe Crystal::Tracing::StatsCommand do
+  it "parses stdin" do
+    stdin = IO::Memory.new <<-TRACE
+    gc malloc t=410557 d=9012 size=16
+    gc malloc t=482582 d=401 size=4 atomic=1
+    gc malloc t=493775 d=128 thread=7f0ea62bd740 size=144
+    sched spawn t=520355 d=-1 thread=7f0ea62bd740 fiber=7f0ea6299f00
+    sched enqueue t=530598 d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00
+    gc malloc t=550326 d=222 thread=7f0ea62bd740 size=24
+    gc collect t=561057 d=79489 thread=7f0ea62bd740
+    gc heap_resize t=102125791993927 d=-1 thread=7f0ea62bd740 size=131072
+    TRACE
+    stdout = IO::Memory.new
+    stderr = IO::Memory.new
+
+    Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run
+    output = stdout.to_s
+    output.should match(/^gc:malloc events=4 durations=\[.+?\] sizes=\[.+?\]$/m)
+    output.should match(/^gc:collect events=1 durations=\[.+?\]$/m)
+    output.should match(/^gc:heap_resize events=1$/m)
+    output.should match(/^sched:spawn events=1$/m)
+    output.should match(/^sched:enqueue events=1 durations=\[.+?\]$/m)
+    stderr.to_s.should be_empty
+  end
+
+  it "--fast" do
+    stdin = IO::Memory.new <<-TRACE
+    gc malloc t=410557 d=9012 size=16
+    gc malloc t=482582 d=401 size=4 atomic=1
+    gc malloc t=493775 d=128 thread=7f0ea62bd740 size=144
+    sched spawn t=520355 d=-1 thread=7f0ea62bd740 fiber=7f0ea6299f00
+    sched enqueue t=530598 d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00
+    gc malloc t=550326 d=222 thread=7f0ea62bd740 size=24
+    gc collect t=561057 d=79489 thread=7f0ea62bd740
+    gc heap_resize t=102125791993927 d=-1 thread=7f0ea62bd740 size=131072
+    TRACE
+    stdout = IO::Memory.new
+    stderr = IO::Memory.new
+
+    Crystal::Tracing::StatsCommand.new("-", fast: true, stdin: stdin, stdout: stdout, stderr: stderr).run
+    output = stdout.to_s
+    output.should match(/^gc:malloc events=4 duration=[-e\d.]+$/m)
+    output.should match(/^gc:collect events=1 duration=[-e\d.]+$/m)
+    output.should match(/^gc:heap_resize events=1$/m)
+    output.should match(/^sched:spawn events=1$/m)
+    output.should match(/^sched:enqueue events=1 duration=[-e\d.]+$/m)
+    stderr.to_s.should be_empty
+  end
+
+  it "parses file" do
+    stdin = IO::Memory.new ""
+    stdout = IO::Memory.new
+    stderr = IO::Memory.new
+
+    with_tempfile("trace.log") do |path|
+      File.write path, <<-TRACE
+      gc malloc t=410557 d=23724 thread=7f0ea62bd740 size=16
+      gc malloc t=482582 d=9074 thread=7f0ea62bd740 size=4 atomic=1
+      gc malloc t=493775 d=222 thread=7f0ea62bd740 size=24
+      gc collect t=520355 d=79489 thread=7f0ea62bd740
+      TRACE
+
+      Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run
+      output = stdout.to_s
+      output.should contain("gc:malloc events=3 durations=")
+      output.should contain("gc:collect events=1 durations=")
+      stderr.to_s.should be_empty
+    end
+  end
+
+  it "warns about invalid traces" do
+    stdin = IO::Memory.new ""
+    stdout = IO::Memory.new
+    stderr = IO::Memory.new
+
+    with_tempfile("trace.log") do |path|
+      File.write path, <<-TRACE
+      Using compiled compiler at .build/crystal
+      gc malloc t=410557 d=23724 thread=7f0ea62bd740 size=16
+      TRACE
+
+      Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run
+      stdout.to_s.should contain("gc:malloc events=1 durations=")
+      stderr.to_s.should contain("WARN: invalid trace 'Using compiled compiler at .build/crystal'")
+    end
+  end
+
+  it "skips invalid traces when parsing stdin" do
+    stdin = IO::Memory.new <<-TRACE
+      Using compiled compiler at .build/crystal
+      gc malloc t=410557 d=23724 thread=7f0ea62bd740 size=16
+      TRACE
+    stdout = IO::Memory.new
+    stderr = IO::Memory.new
+
+    Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run
+    stdout.to_s.should contain("gc:malloc events=1 durations=")
+    stderr.to_s.should be_empty
+  end
+end

spec/std/crystal/system_spec.cr

@@ -1,48 +1,48 @@
 require "../spec_helper"
 
-private def print_error_to_s(format, *args)
+private def printf_to_s(format, *args)
   io = IO::Memory.new
-  Crystal::System.print_error(format, *args) do |bytes|
+  Crystal::System.printf(format, *args) do |bytes|
     io.write_string(bytes)
   end
   io.to_s
 end
 
 describe "Crystal::System" do
-  describe ".print_error" do
+  describe ".printf" do
     it "works" do
-      print_error_to_s("abcde").should eq("abcde")
+      printf_to_s("abcde").should eq("abcde")
     end
 
     it "supports %d" do
-      print_error_to_s("%d,%d,%d,%d,%d", 0, 1234, Int32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,2147483647,-2147483648,-1")
+      printf_to_s("%d,%d,%d,%d,%d", 0, 1234, Int32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,2147483647,-2147483648,-1")
     end
 
     it "supports %u" do
-      print_error_to_s("%u,%u,%u,%u,%u", 0, 1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,4294967295,2147483648,4294967295")
+      printf_to_s("%u,%u,%u,%u,%u", 0, 1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,4294967295,2147483648,4294967295")
     end
 
     it "supports %x" do
-      print_error_to_s("%x,%x,%x,%x,%x", 0, 0x1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,ffffffff,80000000,ffffffff")
+      printf_to_s("%x,%x,%x,%x,%x", 0, 0x1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,ffffffff,80000000,ffffffff")
     end
 
     # TODO: investigate why this prints `(???)`
     pending_interpreted "supports %p" do
-      print_error_to_s("%p,%p,%p", Pointer(Void).new(0x0), Pointer(Void).new(0x1234), Pointer(Void).new(UInt64::MAX)).should eq("0x0,0x1234,0xffffffffffffffff")
+      printf_to_s("%p,%p,%p", Pointer(Void).new(0x0), Pointer(Void).new(0x1234), Pointer(Void).new(UInt64::MAX)).should eq("0x0,0x1234,0xffffffffffffffff")
     end
 
     it "supports %s" do
-      print_error_to_s("%s,%s,%s", "abc\0def", "ghi".to_unsafe, Pointer(UInt8).null).should eq("abc\0def,ghi,(null)")
+      printf_to_s("%s,%s,%s", "abc\0def", "ghi".to_unsafe, Pointer(UInt8).null).should eq("abc\0def,ghi,(null)")
     end
 
     # BUG: missing downcast_distinct from Tuple(Int64 | UInt64, Int64 | UInt64, Int64 | UInt64, Int64 | UInt64) to Tuple(Int64, Int64, Int64, Int64)
     pending_interpreted "supports %l width" do
       values = {LibC::Long::MIN, LibC::Long::MAX, LibC::LongLong::MIN, LibC::LongLong::MAX}
-      print_error_to_s("%ld,%ld,%lld,%lld", *values).should eq(values.join(','))
+      printf_to_s("%ld,%ld,%lld,%lld", *values).should eq(values.join(','))
 
       values = {LibC::ULong::MIN, LibC::ULong::MAX, LibC::ULongLong::MIN, LibC::ULongLong::MAX}
-      print_error_to_s("%lu,%lu,%llu,%llu", *values).should eq(values.join(','))
-      print_error_to_s("%lx,%lx,%llx,%llx", *values).should eq(values.join(',', &.to_s(16)))
+      printf_to_s("%lu,%lu,%llu,%llu", *values).should eq(values.join(','))
+      printf_to_s("%lx,%lx,%llx,%llx", *values).should eq(values.join(',', &.to_s(16)))
     end
   end
 end

src/compiler/crystal/command.cr

@@ -48,6 +48,7 @@ class Crystal::Command
         implementations          show implementations for given call in location
         unreachable              show methods that are never called
         types                    show type of main variables
+        trace                    analyze trace logs
         --help, -h               show this help
     USAGE
 
@@ -199,6 +200,9 @@ class Crystal::Command
     when "unreachable".starts_with?(tool)
       options.shift
       unreachable
+    when "trace".starts_with?(tool)
+      options.shift
+      trace
     when "--help" == tool, "-h" == tool
       puts COMMANDS_USAGE
       exit

src/compiler/crystal/command/trace.cr

@@ -0,0 +1,49 @@
+class Crystal::Command
+  private def trace
+    command = "stats"
+    color = true
+    fast = false
+
+    OptionParser.parse(@options) do |opts|
+      opts.banner = <<-USAGE
+        Usage: crystal tool trace [command] [- | file or directory ...]
+
+        Analyzes trace logs.
+
+        If a file or directory is omitted, the 'trace.log' file in the
+        working directory will be used. To analyze STDIN use '-' in place
+        of any path arguments.
+
+        Commands:
+        USAGE
+
+      opts.on("stats", "Generate stats from a trace file (default)") do
+        command = "stats"
+      end
+
+      opts.on("--fast", "Skip min/max/mean/stddev details for faster processing") do
+        fast = true
+      end
+
+      opts.on("--no-color", "Disable colored output") do
+        color = false
+      end
+
+      opts.on("-h", "--help", "Show this message") do
+        puts opts
+        exit
+      end
+    end
+
+    input = options.first? || "trace.log"
+
+    case command
+    when "stats"
+      if input == "-" || File.exists?(input)
+        Tracing::StatsCommand.new(input, fast: fast, color: color).run
+      else
+        error "file '#{input}' does not exist"
+      end
+    end
+  end
+end