Many Innovative FlameGraph using in Different Scenarios

stackcollapse-crashbt.pl

@@ -0,0 +1,160 @@
+#!/usr/bin/perl -w
+
+use strict;
+use Getopt::Long;
+
+my %collapsed;
+my @stack;
+
+my $command;
+my $cpu;
+my $func_addr;
+my $func_name;
+my $include_pname;
+my $no_cpu = 0;
+my $no_taskaddr = 0;
+my $pid;
+my $pname;
+my $stack_addr;
+my $taskaddr;
+
+
+GetOptions('no_taskaddr' => \$no_taskaddr,
+	   'no_cpu' => \$no_cpu)
+or die <<USAGE_END;
+USAGE: $0 [options] infile > outfile\n
+	--no_taskaddr		# Don't generate taskaddr to eliminate the stacksize
+	--no_cpu		# Don't generate the stack based on the CPU number to eliminate the stacksize\n
+USAGE_END
+
+sub remember_stack {
+	my ($stack, $count) = @_;
+	$collapsed{$stack} += $count;
+}
+
+
+sub summarize_stack_and_cleanup {
+
+	if (!$no_taskaddr) {
+		unshift @stack, "$pname($pid) task_struct:0x$taskaddr";
+	} else {
+		unshift @stack, "$pname";
+	}
+
+	if (!$no_cpu) {
+		unshift @stack, "CPU_$cpu";
+	}
+
+	remember_stack(join(";", @stack), 1);
+
+	undef @stack;
+	undef $command;
+	undef $cpu;
+	undef $func_addr;
+	undef $func_name;
+	undef $pid;
+	undef $pname;
+	undef $stack_addr;
+	undef $taskaddr;
+}
+
+
+#
+# Main loop
+#
+while (defined($_ = <>)) {
+
+	# find the name of the process in the first line of callstack of ftrace.
+	# "bt -a" output ex: 'PID: 2045758  TASK: ffff9b70103e0000  CPU: 0   COMMAND: "ms_pipe_read"'
+	if (/^\s*PID\:\s+(\d+)\s+TASK\:\s+([a-f\d]+)\s+CPU\:\s+(\d+)\s+COMMAND\:\s+\"(.+)\"/) {
+		if (defined $pname) {
+			# The sample count flamegraph needs to summarize stack here
+			summarize_stack_and_cleanup();
+		}
+		$pid = $1;
+		$taskaddr = $2;
+		$cpu = $3;
+		$pname = $4;
+		# print "pid: $pid, taskaddr: $taskaddr, cpu: $cpu, command: $pname\n";
+
+		next;
+	}
+
+	# "bt -a" output:
+	# PID: 0      TASK: ffff9b769861da00  CPU: 1   COMMAND: "swapper/1"
+	#  #0 [fffffe0000034e40] crash_nmi_callback at ffffffff85059c07
+	#  #1 [fffffe0000034e50] nmi_handle at ffffffff850322d0
+	#  #2 [fffffe0000034ea8] default_do_nmi at ffffffff85032784
+	#  #3 [fffffe0000034ec8] do_nmi at ffffffff85032992
+	#  #4 [fffffe0000034ef0] end_repeat_nmi at ffffffff85a01a62
+	#     [exception RIP: mwait_idle+0x77]
+	#     RIP: ffffffff859c7557  RSP: ffffbf214c90be88  RFLAGS: 00000246
+	#     RAX: 0000000000000000  RBX: 0000000000000001  RCX: 0000000000000000
+	#     RDX: 0000000000000000  RSI: 0000000000000000  RDI: 0000000000000000
+	#     RBP: ffffbf214c90be98   R8: 0000000000000000   R9: 0000000000000002
+	#     R10: ffffbf214c90be18  R11: 000000000000406c  R12: 0000000000000001
+	#     R13: ffff9b769861da00  R14: 0000000000000000  R15: 0000000000000000
+	#     ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
+	# --- <NMI exception stack> ---
+	#  #5 [ffffbf214c90be88] mwait_idle at ffffffff859c7557
+	#  #6 [ffffbf214c90bea0] arch_cpu_idle at ffffffff85039e15
+	#  #7 [ffffbf214c90beb0] default_idle_call at ffffffff859c78f3
+	#  #8 [ffffbf214c90bec0] do_idle at ffffffff850d9bda
+	#  #9 [ffffbf214c90bf00] cpu_startup_entry at ffffffff850d9e43
+	# #10 [ffffbf214c90bf28] start_secondary at ffffffff8505b08b
+	# #11 [ffffbf214c90bf50] secondary_startup_64 at ffffffff850000d5
+	# >8-----------------------8<
+	# PID: 253681  TASK: ffff9b8a66a2bc00  CPU: 24  COMMAND: "jujud"
+	#  #0 [ffffbf216c013500] __schedule at ffffffff859c21a6
+	#  #1 [ffffbf216c0135a0] schedule at ffffffff859c26b6
+	#  #2 [ffffbf216c0135b8] schedule_timeout at ffffffff859c67db
+	#  #3 [ffffbf216c013638] wait_for_completion at ffffffff859c3284
+	#  #4 [ffffbf216c013698] xfs_buf_submit_wait at ffffffffc0d197bf [xfs]
+	#  #5 [ffffbf216c0136c0] xfs_bwrite at ffffffffc0d19cb4 [xfs]
+	#  #6 [ffffbf216c0136e0] xfs_reclaim_inode at ffffffffc0d23f43 [xfs]
+	#  #7 [ffffbf216c013730] xfs_reclaim_inodes_ag at ffffffffc0d2419c [xfs]
+	#  #8 [ffffbf216c0138c0] xfs_reclaim_inodes_nr at ffffffffc0d25383 [xfs]
+	#  #9 [ffffbf216c0138e0] xfs_fs_free_cached_objects at ffffffffc0d38699 [xfs]
+	# #10 [ffffbf216c0138f0] super_cache_scan at ffffffff8528818a
+	# #11 [ffffbf216c013948] shrink_slab at ffffffff851f21bb
+	# #12 [ffffbf216c013a18] shrink_slab at ffffffff851f2459
+	# #13 [ffffbf216c013a28] shrink_node at ffffffff851f7458
+	# #14 [ffffbf216c013ab0] do_try_to_free_pages at ffffffff851f774e
+	# #15 [ffffbf216c013b18] try_to_free_pages at ffffffff851f7ab1
+	# #16 [ffffbf216c013ba0] __alloc_pages_slowpath at ffffffff851e5099
+	# #17 [ffffbf216c013cb8] __alloc_pages_nodemask at ffffffff851e5e19
+	# #18 [ffffbf216c013d20] alloc_pages_vma at ffffffff85248152
+	# #19 [ffffbf216c013d68] do_huge_pmd_anonymous_page at ffffffff8525fcc7
+	# #20 [ffffbf216c013dc0] __handle_mm_fault at ffffffff8521c0a7
+	# #21 [ffffbf216c013e78] handle_mm_fault at ffffffff8521c88c
+	# #22 [ffffbf216c013ea8] __do_page_fault at ffffffff850783b1
+	# #23 [ffffbf216c013f20] do_page_fault at ffffffff8507861e
+	# #24 [ffffbf216c013f50] page_fault at ffffffff85a01635
+	if (defined $pname) {
+		if (/\s*\#\d+\s+\[([a-f\d]+)\]\s+(\w+)\s+at\s+([a-f\d]+)\s*(\[\w+\])*$/) {
+			$stack_addr = $1;
+			$func_name = $2;
+			$func_addr = $3;
+			if (defined $4) {
+				unshift @stack, "$func_name $4 <0x$func_addr>";
+			} else {
+				unshift @stack, "$func_name <0x$func_addr>";
+			}
+			# print "stack_addr: $stack_addr, func_name: $func_name, func_addr: $func_addr\n";
+		} elsif (/\s*\-\-\-\s+\<NMI\s+exception\s+stack\>\s+\-\-\-/) {
+
+			# print $_;
+			$func_name = "<NMI stack ↑>";
+			unshift @stack, $func_name;
+			# print "func_name: $func_name\n";
+		# Parse to any other weird lines which is not the stack trace
+		# or the kernel_stack line.
+		} else {
+			next;
+		}
+	}
+}
+
+foreach my $k (sort { $a cmp $b } keys %collapsed) {
+	print "$k $collapsed{$k}\n";
+}

stackcollapse-ftracelat.pl

@@ -0,0 +1,214 @@
+#!/usr/bin/perl -w
+
+use strict;
+use Getopt::Long;
+
+my %collapsed;
+my @stack;
+my @time_stack;
+
+my $addr_offset;
+my $blockseconds;
+my $comm;
+my $cpu;
+my $date;
+my $dtype; # dumpstack type
+my $func_name;
+my $gfp_flags;
+my $hostname;
+my $include_all_calltrace;
+my $include_block_seconds;
+my $include_debug;
+my $include_no_offset;
+my $include_no_page_order;
+my $include_no_page_type;
+my $include_no_pname;
+my $kernelversion;
+my $latency = 0;
+my $lines_skip_before_next_stack = 0;
+my $nr_line = 0;
+my $pid;
+my $pname;
+my $oom_score_adj;
+my $order;
+my $time_accumulator = 0;
+my $tsp;
+
+
+GetOptions('all_calltrace' => \$include_all_calltrace,
+	   'block_seconds' => \$include_block_seconds,
+	   'debug' => \$include_debug,
+	   'no_offset' => \$include_no_offset,
+	   'no_page_order' => \$include_no_page_order,
+	   'no_page_type' => \$include_no_page_type,
+	   'no_process_name' => \$include_no_pname)
+or die <<USAGE_END;
+USAGE: $0 [options] infile > outfile\n
+	--all_calltrace		# Show all the call trace even there is no OOM/hungtask/soft lockup error.
+	--debug			# Enable the debug message
+	--no_offset		# Exclude the address offset from the symbol name.
+				# The stack merge will be better and simplied.
+				# However, by looking at the Flamegraph, it's
+				# not useful when addr2line is needed to
+				# identify the exact code piece.
+
+OOM Call Trace Options:
+	--no_page_order		# Don't generate the flamegraph based on the page order
+	--no_page_type		# Don't include the gfp_flgs in the stack
+	--process_name		# include process names to isolate callstack
+
+HungTask/Soft Lockup options:
+	--block_seconds		# Shows the blocked seconds with the process
+				# name. By default, the block seconds is not
+				# showed in the dump stack to facilitate the
+				# stack merge.\n
+USAGE_END
+
+
+sub debug_log {
+	my ($message) = @_;
+	print "$message" if $include_debug;
+}
+
+sub remember_stack {
+	my ($stack, $count) = @_;
+	$collapsed{$stack} += $count*1000;
+	debug_log "$stack $collapsed{$stack}\n";
+}
+
+sub undefine_variables {
+	undef $addr_offset;
+	undef $comm;
+	undef $cpu;
+	undef $date;
+	undef $dtype;
+	undef $func_name;
+	undef $gfp_flags;
+	undef $hostname;
+	undef $kernelversion;
+	undef $oom_score_adj;
+	undef $order;
+	undef $pid;
+	undef $pname;
+	undef @stack;
+	undef $tsp;
+}
+
+sub summarize_stack_and_cleanup {
+	my ($pop_func, $undef_var, $latency) = @_;
+
+out:
+	remember_stack(join(";", @stack), $latency);
+	pop @stack if $pop_func;
+	undefine_variables() if $undef_var;
+}
+
+
+#
+# Main loop
+#
+while (defined($_ = <>)) {
+
+	$nr_line = $.;
+
+	# 1). Function start
+	# Processor-31570 [007] 2872459.738331: funcgraph_entry:                   |  SyS_writev() {
+	if (/\s*(.+)\s+\[(\d+)\]\s+(\d+\.\d+)\:\s+(funcgraph_entry)\:\s+\|\s+(.+)\(\)\s+\{/) {
+		debug_log "##### function_entry #####\n";
+		$pname = $1;
+		$cpu = $2;
+		$tsp = $3;
+		$func_name = $5;
+
+		push @time_stack, $time_accumulator;
+		push @time_stack, $func_name;
+		$time_accumulator = 0; # Reset the time for each function
+
+=pod
+		if (!@stack) {
+			unshift @stack, $pname if ($pname);
+			unshift @stack, "CPU# $cpu" if ($cpu);
+		}
+=cut
+
+		debug_log "@time_stack\n";
+		push @stack, "$func_name";
+		next; # ready to parse the dump_stack call trace
+	}
+
+	# 2). Single function
+	# Processor-31570 [007] 2872459.738333: funcgraph_entry:        0.376 us   |    fget_light();
+	# Processor-31570 [006] 2872460.164409: funcgraph_entry:      + 11.008 us  | __x2apic_send_IPI_mask();
+	# if (/\s*(.+)\s+\[(\d+)\]\s+(\d+\.\d+)\:\s+(.*)\:\s+(.*\s*\d+\.\d+)\s+.+\s+\|\s+(.+\(\));/) {
+	#
+	#   Documentation/trace/ftrace.rst
+	#   + means that the function exceeded 10 usecs.
+	#   ! means that the function exceeded 100 usecs.
+	#   # means that the function exceeded 1000 usecs.
+	#   * means that the function exceeded 10 msecs.
+	#   @ means that the function exceeded 100 msecs.
+	#   $ means that the function exceeded 1 sec.
+
+	if (/\s*(.+)\s+\[(\d+)\]\s+(\d+\.\d+)\:\s+(funcgraph_entry)\:\s+[+!#*@$]?\s*(\d+\.\d+)\s+.+\s+\|\s+(.+)\(\);/) {
+		debug_log "##### Single function #####\n";
+		$pname = $1;
+		$cpu = $2;
+		$tsp = $3;
+		$latency = $5;
+		$func_name = $6;
+		push @stack, "$func_name";
+
+		$time_accumulator += $latency; # accumulate the time inside the function
+		summarize_stack_and_cleanup(1, 0, $latency); # pop:true, undef:false
+		next; # ready to parse the dump_stack call trace
+	}
+
+	# 3). Function end
+	# Processor-31570 [007] 2872459.738421: funcgraph_exit:       + 15.597 us  |          }
+	# if (/\s*(.+)\s+\[(\d+)\]\s+(\d+\.\d+)\:\s+(.*)\:\s+(.*\s*\d+\.\d+)\s+.+\s+\|\s+\}/) {
+	if (/\s*(.+)\s+\[(\d+)\]\s+(\d+\.\d+)\:\s+(funcgraph_exit)\:\s+[+!#*@$]?\s*(\d+\.\d+)\s+.+\s+\|\s+\}/) {
+		$pname = $1;
+		$cpu = $2;
+		$tsp = $3;
+		$latency = $5;
+		debug_log "L$nr_line: $tsp $pname $cpu $latency\n";
+
+		my $save_time_accumulator;
+		debug_log "##### funcgraph_exit } #####\n";
+		my $len_time_stack = scalar @time_stack;
+		debug_log "len_time_stack: $len_time_stack\n";
+		debug_log "\$time_stack[$len_time_stack - 1]: $time_stack[$len_time_stack - 1]\n";
+		$_ = $time_stack[$len_time_stack - 1];
+
+		debug_log "\$_: $_\n";
+		debug_log "\@stack: @stack\n";
+		debug_log "\@time_stack: @time_stack\n";
+
+		until ($_ =~ /[^\d\.]/) {
+			$time_accumulator += $_;
+			$_ = pop @time_stack;
+			debug_log "pop value: $_\n";
+			$len_time_stack = scalar @time_stack;
+			$_ = $time_stack[$len_time_stack - 1];
+		}
+
+		pop @time_stack;
+		debug_log "\@time_stack: @time_stack\n";
+
+		$save_time_accumulator = $latency;
+		debug_log "$latency -= $time_accumulator\n";
+		$latency -= $time_accumulator;
+		debug_log "final latency: $latency\n";
+
+		$time_accumulator = $save_time_accumulator;
+		debug_log "new time_accumulator: $time_accumulator\n";
+
+		summarize_stack_and_cleanup(1, 0, $latency);
+		next; # ready to parse the dump_stack call trace
+
+	}
+}
+
+foreach my $k (sort { $a cmp $b } keys %collapsed) {
+	print "$k $collapsed{$k}\n";
+}