Merge pull request #168 from jonhoo/discrepancies

perf: fix a number of corner-cases for small traces

.gitmodules

@@ -1,3 +1,3 @@
 [submodule "flamegraph"]
 	path = flamegraph
-	url = https://github.com/brendangregg/FlameGraph.git
+	url = https://github.com/jonhoo/FlameGraph.git

src/collapse/perf.rs

@@ -158,7 +158,13 @@ impl CollapsePrivate for Folder {
         // information to get started). Only read one stack, however, as we would
         // like the remaining stacks to be processed on the worker threads.
         let mut line_buffer = String::new();
-        self.process_single_stack(&mut line_buffer, reader, occurrences)?;
+        let eof = self.process_single_stack(&mut line_buffer, reader, occurrences)?;
+
+        if eof {
+            // If we hit EOF, it may be that the input was completely empty.
+            // In that case, we don't do the event_filter assertion below.
+            return Ok(());
+        }
 
         // If we didn't find an event filter, there is something wrong with
         // our processing code.
@@ -275,6 +281,9 @@ impl Folder {
         loop {
             line_buffer.clear();
             if reader.read_line(line_buffer)? == 0 {
+                if !self.stack.is_empty() {
+                    self.after_event(occurrences);
+                }
                 return Ok(true);
             }
             if line_buffer.starts_with('#') {
@@ -287,12 +296,17 @@ impl Folder {
             } else if self.in_event {
                 self.on_stack_line(line);
             } else {
+                assert!(self.stack.is_empty());
                 self.on_event_line(line);
+                if !self.stack.is_empty() {
+                    // we must have hit a combined event/stack line
+                    self.after_event(occurrences);
+                }
             }
         }
     }
 
-    fn event_line_parts(line: &str) -> Option<(&str, &str, &str)> {
+    fn event_line_parts(line: &str) -> Option<(&str, &str, &str, usize)> {
         let mut word_start = 0;
         let mut all_digits = false;
         let mut last_was_space = false;
@@ -310,7 +324,7 @@ impl Folder {
                     };
                     // also trim comm in case multiple spaces were used to separate
                     let comm = line[..(word_start - 1)].trim();
-                    return Some((comm, pid, tid));
+                    return Some((comm, pid, tid, idx + 1));
                 }
                 word_start = idx + 1;
                 all_digits = true;
@@ -338,29 +352,57 @@ impl Folder {
     //     java 12688/12764 6544038.708352: cpu-clock:
     //     V8 WorkerThread 24636/25607 [000] 94564.109216: cycles:
     //     vote   913    72.176760:     257597 cycles:uppp:
+    //     false 64414 20110.539270:      34467 cycles:u:  ffffffff9aa3c8de [unknown] ([unknown])
     fn on_event_line(&mut self, line: &str) {
         self.in_event = true;
 
-        if let Some((comm, pid, tid)) = Self::event_line_parts(line) {
-            if let Some(event) = line.rsplitn(2, ' ').next() {
-                if event.ends_with(':') {
-                    let event = &event[..(event.len() - 1)];
-
-                    if let Some(ref event_filter) = self.event_filter {
-                        if event != event_filter {
-                            self.skip_stack = true;
-                            return;
-                        }
-                    } else {
-                        // By default only show events of the first encountered event type.
-                        // Merging together different types, such as instructions and cycles,
-                        // produces misleading results.
-                        logging::filtering_for_events_of_type(event);
-                        self.event_filter = Some(event.to_string());
+        if let Some((comm, pid, tid, end)) = Self::event_line_parts(line) {
+            let mut by_colons = line[end..].splitn(3, ':').skip(1);
+            let event = by_colons
+                .next()
+                .and_then(|has_event| has_event.rsplit(' ').next());
+            if let Some(event) = event {
+                if let Some(ref event_filter) = self.event_filter {
+                    if event != event_filter {
+                        self.skip_stack = true;
+                        return;
                     }
+                } else {
+                    // By default only show events of the first encountered event type.
+                    // Merging together different types, such as instructions and cycles,
+                    // produces misleading results.
+                    logging::filtering_for_events_of_type(event);
+                    self.event_filter = Some(event.to_string());
                 }
             }
 
+            // some event lines _include_ a stack line if the stack only has one frame.
+            // in that case, the event will be followed by the stack.
+            let single_stack = if let Some(post_event) = by_colons.next() {
+                // we need to deal with a couple of cases here:
+                //
+                //     vote   913    72.176760:     257597 cycles:uppp:
+                //     false 64414 20110.539270:      34467 cycles:u:  ffffffff9aa3c8de [unknown] ([unknown])
+                //     false 64414 20110.539270:      34467 cycles:  ffffffff9aa3c8de [unknown] ([unknown])
+                //
+                // the first should not be handled as a stack, whereas the latter two both should
+                // the trick is going to be to trim until we encounter a space or a :, whichever
+                // comes first, and then evaluate from there.
+                let post_event_start = post_event
+                    .find(|c| c == ':' || c == ' ')
+                    .map(|i| i + 1)
+                    .unwrap_or(0);
+                let post_event = post_event[post_event_start..].trim();
+                if !post_event.is_empty() {
+                    // we have a stack!
+                    Some(post_event)
+                } else {
+                    None
+                }
+            } else {
+                None
+            };
+
             // XXX: re-use existing memory in pname if possible
             self.pname = comm.replace(' ', "_");
             if self.opt.include_tid {
@@ -372,6 +414,11 @@ impl Folder {
                 self.pname.push_str("-");
                 self.pname.push_str(pid);
             }
+
+            if let Some(stack_line) = single_stack {
+                self.on_stack_line(stack_line);
+                self.in_event = false;
+            }
         } else {
             logging::weird_event_line(line);
             self.in_event = false;

tests/collapse-perf.rs

@@ -228,6 +228,9 @@ macro_rules! collapse_perf_tests {
 }
 
 collapse_perf_tests! {
+    collapse_perf_no_events,
+    collapse_perf_single_line_stacks,
+    collapse_perf_single_event,
     collapse_perf_go_stacks,
     collapse_perf_java_inline
 }

tests/data/collapse-perf/results/go-stacks-collapsed.txt

@@ -1,4 +1,5 @@
 go;[unknown];[unknown];runtime.main;main.main;cmd/go/internal/run.runRun;cmd/go/internal/load.PackagesAndErrors;cmd/go/internal/load.loadPackage;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;go/build.(*Context).Import;go/build.(*Context).matchFile;go/build.readImports;go/build.(*importReader).readKeyword;go/build.(*importReader).peekByte;go/build.(*importReader).readByte 1
+go;[unknown];[unknown];runtime.main;main.main;cmd/go/internal/run.runRun;cmd/go/internal/load.PackagesAndErrors;cmd/go/internal/load.loadPackage;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;cmd/go/internal/load.(*Package).load;cmd/go/internal/load.LoadImport;go/build.(*Context).Import;go/parser.ParseFile;go/parser.(*parser).parseFile;go/parser.(*parser).expectSemi;go/parser.(*parser).next;go/parser.(*parser).consumeComment 1
 go;[unknown];x_cgo_notify_runtime_init_done;runtime.main;main.init;cmd/go/internal/base.init;cmd/go/internal/cfg.init;go/build.init;go/doc.init;text/template.init;text/template.init.ializers;text/template.createValueFuncs;text/template.addValueFuncs;runtime.mapassign_faststr 1
 go;[unknown];x_cgo_notify_runtime_init_done;runtime.main;main.init;cmd/go/internal/bug.init;cmd/go/internal/envcmd.init;cmd/go/internal/modload.init;cmd/go/internal/modfetch.init;cmd/go/internal/get.init;cmd/go/internal/work.init;cmd/go/internal/work.init.ializers;regexp.MustCompile;regexp.compile;regexp/syntax.Compile;runtime.growslice 1
 go;[unknown];x_cgo_notify_runtime_init_done;runtime.main;main.init;cmd/go/internal/bug.init;cmd/go/internal/envcmd.init;cmd/go/internal/modload.init;cmd/go/internal/modfetch.init;cmd/go/internal/get.init;cmd/go/internal/work.init;cmd/go/internal/work.init.ializers;regexp.MustCompile;regexp.compile;regexp/syntax.Parse;regexp/syntax.(*parser).literal;regexp/syntax.(*parser).push;regexp/syntax.(*parser).maybeConcat;runtime.growslice 1

tests/data/collapse-perf/results/java-inline-collapsed.txt

@@ -1,6 +1,6 @@
 java;[unknown];__GI___libc_write 6
 java;[unknown];__GI___libc_write;entry_SYSCALL_64_after_hwframe;do_syscall_64 2
-java;[unknown];__GI___libc_write;entry_SYSCALL_64_after_hwframe;do_syscall_64;ksys_write;__fdget_pos;__fget_light 2
+java;[unknown];__GI___libc_write;entry_SYSCALL_64_after_hwframe;do_syscall_64;ksys_write;__fdget_pos;__fget_light 3
 java;[unknown];__GI___libc_write;entry_SYSCALL_64_after_hwframe;do_syscall_64;ksys_write;fput 1
 java;[unknown];__GI___libc_write;entry_SYSCALL_64_after_hwframe;do_syscall_64;ksys_write;vfs_write;__vfs_write;tty_write;n_tty_write 1
 java;[unknown];__GI___libc_write;entry_SYSCALL_64_after_hwframe;do_syscall_64;ksys_write;vfs_write;__vfs_write;tty_write;n_tty_write;_raw_spin_unlock_irqrestore 1

tests/data/collapse-perf/results/single-event-collapsed.txt

@@ -0,0 +1 @@
+boa_cli;[unknown];boa_cli::main;boa::realm::Realm::create;boa::realm::Realm::create_instrinsics;boa::builtins::console::create_constructor;boa::builtins::value::ValueData::set_field_slice;boa::builtins::value::ValueData::set_field;boa::builtins::object::internal_methods_trait::ObjectInternalMethods::set;<boa::builtins::object::Object as boa::builtins::object::internal_methods_trait::ObjectInternalMethods>::define_own_property;boa::builtins::value::to_value;<alloc::string::String as boa::builtins::value::ToValue>::to_value;gc::Gc<T>::new;gc::gc::GcBox<T>::new;std::thread::local::LocalKey<T>::with;std::thread::local::LocalKey<T>::try_with;gc::gc::GcBox<T>::new::_{{closure}};gc::gc::collect_garbage;gc::gc::collect_garbage::mark;gc::gc::GcBox<T>::trace_inner;<gc::GcCell<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<boa::environment::global_environment_record::GlobalEnvironmentRecord as gc::trace::Trace>::trace;<boa::environment::global_environment_record::GlobalEnvironmentRecord as gc::trace::Trace>::trace::mark;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<boa::environment::object_environment_record::ObjectEnvironmentRecord as gc::trace::Trace>::trace;<boa::environment::object_environment_record::ObjectEnvironmentRecord as gc::trace::Trace>::trace::mark;<gc::Gc<T> as gc::trace::Trace>::trace;gc::gc::GcBox<T>::trace_inner;<boa::builtins::value::ValueData as gc::trace::Trace>::trace;<boa::builtins::value::ValueData as gc::trace::Trace>::trace::mark;<gc::GcCell<T> as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace::mark;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace::mark;<boa::builtins::property::Property as gc::trace::Trace>::trace;<boa::builtins::property::Property as gc::trace::Trace>::trace::mark;<core::option::Option<T> as gc::trace::Trace>::trace;<core::option::Option<T> as gc::trace::Trace>::trace::mark;<gc::Gc<T> as gc::trace::Trace>::trace;gc::gc::GcBox<T>::trace_inner;<boa::builtins::value::ValueData as gc::trace::Trace>::trace;<boa::builtins::value::ValueData as gc::trace::Trace>::trace::mark;<gc::GcCell<T> as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace::mark;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace::mark;<boa::builtins::property::Property as gc::trace::Trace>::trace;<boa::builtins::property::Property as gc::trace::Trace>::trace::mark;<core::option::Option<T> as gc::trace::Trace>::trace;<core::option::Option<T> as gc::trace::Trace>::trace::mark;<gc::Gc<T> as gc::trace::Trace>::trace;gc::gc::GcBox<T>::trace_inner;<boa::builtins::value::ValueData as gc::trace::Trace>::trace;<boa::builtins::value::ValueData as gc::trace::Trace>::trace::mark;<gc::GcCell<T> as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace::mark;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace::mark;<boa::builtins::property::Property as gc::trace::Trace>::trace;<boa::builtins::property::Property as gc::trace::Trace>::trace::mark;<core::option::Option<T> as gc::trace::Trace>::trace;<core::option::Option<T> as gc::trace::Trace>::trace::mark;<gc::Gc<T> as gc::trace::Trace>::trace;gc::gc::GcBox<T>::trace_inner;<boa::builtins::value::ValueData as gc::trace::Trace>::trace;<boa::builtins::value::ValueData as gc::trace::Trace>::trace::mark;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<gc::GcCell<T> as gc::trace::Trace>::trace;<boa::builtins::function::Function as gc::trace::Trace>::trace;<boa::builtins::function::Function as gc::trace::Trace>::trace::mark;<boa::builtins::function::NativeFunction as gc::trace::Trace>::trace;<boa::builtins::function::NativeFunction as gc::trace::Trace>::trace::mark;<boa::builtins::object::Object as gc::trace::Trace>::trace;<boa::builtins::object::Object as gc::trace::Trace>::trace::mark;<alloc::boxed::Box<T> as gc::trace::Trace>::trace;<alloc::boxed::Box<T> as gc::trace::Trace>::trace::mark;<std::collections::hash::map::HashMap<K,V> as gc::trace::Trace>::trace 1

tests/data/collapse-perf/results/single-line-stacks-collapsed.txt

@@ -0,0 +1,2 @@
+false;[unknown] 1
+false;_dl_start 1