add sample size in msec to profiler

core/core.stanza

@@ -9606,22 +9606,25 @@ public defn all?<?T> (pred?: T -> True|False, xs:Seqable<?T>) -> True|False :
    for xs-seq in xs do-seq :
       let loop () :
          if empty?(xs-seq) : true
-         else : pred?(next(xs-seq)) and loop()
+         else if pred?(next(xs-seq)) : loop()
+         else : false
 
 public defn all?<?T,?S> (pred?: (T,S) -> True|False, xs:Seqable<?T>, ys:Seqable<?S>) -> True|False :
    for xs-seq in xs do-seq :
       for ys-seq in ys do-seq :
          let loop () :
             if empty?(xs-seq) or empty?(ys-seq) : true
-            else : pred?(next(xs-seq), next(ys-seq)) and loop()
+            else if pred?(next(xs-seq), next(ys-seq)) : loop()
+            else : false
 
 public defn all?<?T,?S,?U> (pred?: (T,S,U) -> True|False, xs:Seqable<?T>, ys:Seqable<?S>, zs:Seqable<?U>) -> True|False :
    for xs-seq in xs do-seq :
       for ys-seq in ys do-seq :
          for zs-seq in zs do-seq :
             let loop () :
                if empty?(xs-seq) or empty?(ys-seq) or empty?(zs-seq) : true
-               else : pred?(next(xs-seq), next(ys-seq), next(zs-seq)) and loop()
+               else if pred?(next(xs-seq), next(ys-seq), next(zs-seq)) : loop()
+               else : false
 
 public defn none?<?T> (xs:Seqable<?T>, pred?: T -> True|False) -> True|False :
   none?(pred?,xs)
@@ -11221,12 +11224,16 @@ public defmulti name (t:TypeObject) -> String
 
 #if-not-defined(BOOTSTRAP) :
 
+  public var last-profiler-time:Long = 0L
+
   ;Called from app to record stack trace as return addresses in buffer
   ;Demarcate end of each coroutine stack with -2 and end trace with -1
   lostanza defn profile-stack-trace () -> ref<False> :
     val vms:ptr<VMState> = call-prim flush-vm()
     [vms.profile-flag] = 2L
     val buffer = vms.profile-buffer
+    add(buffer, call-c clib/current_time_ms())
+    add(buffer, -2L) ; time marker
     labels :
       begin :
         goto loop(current-coroutine)

core/profiler.stanza

@@ -17,9 +17,13 @@ public defstruct ProfileInfo :
 with:
   printer => true
 
+defstruct ProfileStackIdTrace :
+  msecs : Int
+  ids : Tuple<Int>
+
 public defstruct ProfileResult :
   info : Tuple<ProfileInfo>
-  id-traces : Tuple<Tuple<Int>>
+  id-traces : Tuple<ProfileStackIdTrace>
   msecs : Int
 with:
   printer => true
@@ -50,9 +54,13 @@ defserializer ProfileResultSerializer () :
     info:info
     count:long
 
+  deftype profilestackidtrace (ProfileStackIdTrace) :
+    msecs:int
+    ids:tuple(int)
+
   deftype profileresult (ProfileResult) :
     info:tuple(profileinfo)
-    id-traces:tuple(tuple(int))
+    id-traces:tuple(profilestackidtrace)
     msecs:int
 
 
@@ -89,25 +97,13 @@ lostanza defn build-stack-trace-record-table (trace-table:ptr<core/StackTraceTab
     to-list $ seq(unique, filter({ not empty?(_) }, traces))
 
   ;Count all functions references in stack traces where traces have function ids in them
-  defn count-traces (len:Int, traces:Vector<Tuple<Int>>) -> Array<Long> :
+  defn count-traces (len:Int, traces:Vector<ProfileStackIdTrace>) -> Array<Long> :
     val counts = Array<Long>(len, 0L)
     for trace in traces do :
-      for id in trace do :
+      for id in ids(trace) do :
         counts[id] = counts[id] + 1L
     counts
 
-  ;Split stack trace buffer using delimiter 
-  defn split-buffer (buffer:List<Long>, delimiter:Long) -> List<List<Long>> :
-    let loop (i:Int = 0, buffers:List<List<Long>> = List(), ids:List<Long> = List()) :
-      if i < length(buffer) :
-        val id = buffer[i]
-        if id == delimiter :
-          loop(i + 1, cons(reverse(ids), buffers), List())
-        else :
-          loop(i + 1, buffers, cons(id, ids))
-      else :
-        reverse(buffers)
-
   ;Split stack trace buffer using delimiter 
   defn split-buffer (buffer:Tuple<Long>, delimiter:Long) -> Vector<Tuple<Long>> :
     val res = Vector<Tuple<Long>>()
@@ -120,56 +116,71 @@ lostanza defn build-stack-trace-record-table (trace-table:ptr<core/StackTraceTab
         add(chunk, id)
     res
 
+  defstruct ProfileRawStackTrace :
+    elapsed-time : Long
+    return-addresses : Tuple<Long>
+
   ;Reconsititue full stack traces by splitting up chunks and ordering them properly
-  defn build-stack-traces (buffer:Tuple<Long>) -> Tuple<Tuple<Long>> :
+  defn build-stack-traces (buffer:Tuple<Long>) -> Tuple<ProfileRawStackTrace> :
     val buffers = split-buffer(buffer, -1L)
     ;same as:
     ; to-tuple $ for trace in buffers seq : 
     ;   to-tuple $ reverse $ to-list $ cat-all $ seq(reverse, split-buffer(trace, -2L))
     to-tuple $ for (trace in buffers, k in 0 to false) seq : 
       val res = Vector<Long>()
       val chunks = split-buffer(trace, -2L) ;split full stack trace into coroutine stack traces
-      for i in (length(chunks) - 1) through 0 by -1 do :
+      val elapsed = chunks[0][0]
+      for i in (length(chunks) - 1) to 0 by -1 do :
         val chunk = chunks[i]
         for j in 0 to length(chunk) do :
           add(res, chunk[j])
-      to-tuple(res)
+      ProfileRawStackTrace(elapsed, to-tuple(res))
 
   ;Create function id traces and function info results after profiling
-  lostanza defn collect-profiling (msecs:ref<Int>) -> ref<ProfileResult> :
+  lostanza defn collect-profiling (specd-msecs:ref<Int>) -> ref<ProfileResult> :
     val vms:ptr<core/VMState> = call-prim flush-vm()
     val info:ptr<core/FunctionInfoTable> = vms.function-info
     val counters:ptr<long> = vms.function-counters
     val buffer:ptr<LSLongVector> = vms.profile-buffer as ptr<LSLongVector>
-    val id-traces = Vector<Tuple<Int>>()
+    val id-traces = Vector<ProfileStackIdTrace>()
     val infos = Vector<ProfileInfo>()
 
     if info.length > 0L :
-
+    
       val tab = build-stack-trace-record-table(vms.stack-trace-table) ;For fast lookup of return addresses
       val buffer* = Vector<Long>()
-
+    
       for (var i:long = 0, i < buffer.length, i = i + 1) :
         add(buffer*, new Long{buffer.items[i]})
-
+    
       val traces = build-stack-traces(to-tuple(buffer*)) ;Order and concatenate stack trace chunks
-
+
+      var last_global_elapsed_time:long = 0L
+
       ;Lookup stack trace records and then translate into function ids
       for (var i:long = 0, i < length(traces).value, i = i + 1) :
         val trace = get(traces, new Int{i as int})
+        val global-elapsed = elapsed-time(trace)
+        var msecs:int = 0
+        if last_global_elapsed_time == 0L : ; first trace?
+          msecs = specd-msecs.value
+        else :
+          msecs = (global-elapsed.value - last_global_elapsed_time) as int
+        last_global_elapsed_time = global-elapsed.value
         val trace* = Vector<Int>()
-        for (var j:long = 0, j < length(trace).value, j = j + 1) :
-          val ret = get(trace, new Int{j as int})
+        val addrs = return-addresses(trace)
+        for (var j:long = 1, j < length(addrs).value, j = j + 1) :
+          val ret = get(addrs, new Int{j as int})
           val entry = stack-trace-record(ret.value, vms.stack-trace-table, tab)
           if entry != null :
             val id = entry.function
             if id != -1L :
               add(trace*, new Int{id as int})
-        add(id-traces, to-tuple(trace*))
-
+        add(id-traces, ProfileStackIdTrace(new Int{msecs}, to-tuple(trace*)))
+    
       val len:long = info.length
       val counts = count-traces(new Int{len as int}, id-traces)
-
+    
       ;Collect all FunctionInfos corresponding to ids that occurred on stack at least once
       for (var i:long = 0L, i < len, i = i + 1) :
         val entry = info.entries[i]
@@ -181,7 +192,7 @@ lostanza defn build-stack-trace-record-table (trace-table:ptr<core/StackTraceTab
           val ci = ProfileInfo(new Int{i as int}, package, name, fi, count)
           add(infos, ci)
 
-    return ProfileResult(to-tuple(infos), to-tuple(id-traces), msecs)
+    return ProfileResult(to-tuple(infos), to-tuple(id-traces), specd-msecs)
 
   ;Collect all coverage information from all functions
   lostanza defn collect-coverage () -> ref<Vector<ProfileInfo>> :
@@ -298,7 +309,7 @@ defn with-output-file-stream<?T> (f: FileOutputStream -> ?T, file:FileOutputStre
   finally : close(file)
 
 ; turn profile result into flame graph file format
-public defn stack-collapse (res:ProfileResult, filename:String, top?:True|False = false, depth:Int = 1, silence-prefixes:Tuple<String> = default-silence-prefixes) :
+public defn stack-collapse (res:ProfileResult, filename:String, top?:True|False = false, max-depth:Int = 1000, silence-prefixes:Tuple<String> = default-silence-prefixes) :
   val strings = IntTable<String>()
   val silence-ids = IntSet()
   for elt in info(res) do :
@@ -310,23 +321,21 @@ public defn stack-collapse (res:ProfileResult, filename:String, top?:True|False
     if top? :
       val tops = IntTable<Int>(0)
       for trace in id-traces(res) do :
-        val len = length(trace)
+        val ids = ids(trace)
+        val len = length(ids)
         for off in 1 through 2 do :
           val idx = len - off
           if idx >= 0 :
-            val id = trace[idx]
+            val id = ids[idx]
             tops[id] = tops[id] + 1
       val tops* = reverse $ to-list $ lazy-qsort(value, tops)
       for top in tops* do :
         println(file, "%_: %_" % [value(top) * msecs(res), strings[key(top)]])
     else :
       for trace in id-traces(res) do :
-        var first?:True|False = true
-        for record in trace do :
-          if not silence-ids[record] :
-            print(file, ";") when not first?
-            print(file, strings[record])
-            first? = false
+        for (record in filter({ not silence-ids[_] }, ids(trace)), i in 0 to max-depth) do :
+          print(file, ";") when i > 0
+          print(file, strings[record])
         print(file, " ")
-        println(file, msecs(res))
+        println(file, msecs(trace))