[SAMPLE][PATCH 1/3]BTI: Binary Transport Interface for SystemTap

[SAMPLE][PATCH 1/3]BTI: Binary Transport Interface for SystemTap

[Masami Hiramatsu]

Hi,

I publish Binary Transport Interface (BTI) Patch for SystemTap.
This BTI is a concept prototype which was demonstrated in 2nd Face to
Face meeting.
I attach a core patch of BTI to this mail. But current merge routine
of stpd can not handle binary formatted data correctly. So this patch
requires another patch which adds an option that prohibits merging
to stap, and another merge command.
I post it in following mails.

I measured the performance number of this BTI and compared with
current Ascii Transport Interface (ATI) by using the “gtodbench”
gettimeofday micro benchmark on Pentium4 3.06GHz PC.
The systemtap script with BTI (*1) has about 1.4 micro secs of
processing time. The systemtap script with ATI (*2) has about
4 micro secs of processing time. This performance numbers are
including the overhead of kprobes. Also I measured kprobe’s overhead
on the same PC. That was about 1 micro second.
So, I expects BTI has very low overhead and is useful for tracing
function.

(*1)
probe kernel.function("sys_gettimeofday") {
      trace4(1,2,3,4,5);
}

(*2)
probe kernel.function("sys_gettimeofday") {
      log(string(get_tsc()) . string(get_cpu()) . string(pid()) . string(1) .
string(2). string(3). string(4). string(5));
}

But this interface depends strongly on LKST’s log format. So, I and
Satoshi would like to propose another generic BTI format.

Best Regards,

-- 
Masami HIRAMATSU
2nd Research Dept.
Hitachi, Ltd., Systems Development Laboratory
E-mail: hiramatu@sdl.hitachi.co.jp

Signed-off-by: Masami Hiramatsu <hiramatu@sdl.hitachi.co.jp>

 runtime/runtime.h  |    1 +
 runtime/trace.c    |   48 ++++++++++++++++++++++++++++++++++++++++++++++++
 tapset/tracing.stp |   24 ++++++++++++++++++++++++
 6 files changed, 82 insertions(+), 1 deletion(-)
diff -Narup -x CVS a/buildrun.cxx b/buildrun.cxx
diff -Narup -x CVS a/runtime/runtime.h b/runtime/runtime.h
--- a/runtime/runtime.h	2005-11-29 07:08:39.000000000 +0900
+++ b/runtime/runtime.h	2005-12-05 17:49:59.000000000 +0900
@@ -64,6 +64,7 @@ static struct
 #include "copy.c"
 #include "sym.h"
 #include "alloc.c"
+#include "trace.c"


 /************* Module Stuff ********************/
diff -Narup -x CVS a/runtime/trace.c b/runtime/trace.c
--- a/runtime/trace.c	1970-01-01 09:00:00.000000000 +0900
+++ b/runtime/trace.c	2005-12-05 17:49:36.000000000 +0900
@@ -0,0 +1,48 @@
+#ifndef _TRACE_C_ /* -*- linux-c -*- */
+#define _TRACE_C_
+
+#include <linux/config.h>
+#include <linux/percpu.h>
+#include "io.c"
+
+#define MAX_TRACE_ARGS 16
+
+struct stp_trace_entry_head {
+	unsigned long long tsc;
+	int num;
+	int pid;
+	int cpu;
+	int type;
+};
+
+struct stp_trace_entry {
+	struct stp_trace_entry_head hd;
+	long args[MAX_TRACE_ARGS];
+};
+
+static DEFINE_PER_CPU(struct stp_trace_entry, __trace_entry);
+
+void _stp_trace (int type, int num, ...)
+{
+	va_list args;
+	int cpu = smp_processor_id();
+	int i;
+	
+	struct stp_trace_entry *ent = &per_cpu(__trace_entry, cpu);
+	if (num > MAX_TRACE_ARGS) num = MAX_TRACE_ARGS;
+	ent->hd.cpu = cpu;
+	ent->hd.pid = current->pid;
+	ent->hd.type = type;
+	ent->hd.num = num;
+	va_start(args, num);
+	for (i = 0; i < num; i++) {
+		ent->args[i] = (long)va_arg(args, int64_t);
+	}
+	va_end(args);
+	rdtscll(ent->hd.tsc);
+	_stp_transport_write(ent, sizeof(struct stp_trace_entry_head) +
+			     num*sizeof(long));
+}
+
+
+#endif /* _TRACE_C_ */
diff -Narup -x CVS a/tapset/tracing.stp b/tapset/tracing.stp
--- a/tapset/tracing.stp	1970-01-01 09:00:00.000000000 +0900
+++ b/tapset/tracing.stp	2005-12-05 17:49:36.000000000 +0900
@@ -0,0 +1,24 @@
+// trace_event tapset
+// Copyright (C) 2005 Hitachi, Ltd., Systems Development Laboratory
+//
+// This file is part of systemtap, and is free software.  You can
+// redistribute it and/or modify it under the terms of the GNU General
+// Public License (GPL); either version 2, or (at your option) any
+// later version.
+
+function trace1 (type:long, arg:long) %{
+    _stp_trace(THIS->type, 1, THIS->arg);
+%}
+
+function trace2 (type:long, arg1:long, arg2:long) %{
+    _stp_trace(THIS->type, 2, THIS->arg1, THIS->arg2);
+%}
+
+function trace3 (type:long, arg1:long, arg2:long, arg3:long) %{
+    _stp_trace(THIS->type, 3, THIS->arg1, THIS->arg2, THIS->arg3);
+%}
+
+function trace4 (type:long, arg1:long, arg2:long, arg3:long, arg4:long) %{
+	_stp_trace(THIS->type, 4, THIS->arg1, THIS->arg2, THIS->arg3, THIS->arg4);
+%}
+

Re: [SAMPLE][PATCH 1/3]BTI: Binary Transport Interface for SystemTap

[Frank Ch. Eigler]

hiramatu wrote:

> [...]  The systemtap script with BTI (*1) has about 1.4 micro secs
> of processing time. The systemtap script with ATI (*2) has about 4
> micro secs of processing time. [...]

> (*2)
> probe kernel.function("sys_gettimeofday") {
>       log(string(get_tsc()) . string(get_cpu()) . string(pid()) . string(1)=
>  .
> string(2). string(3). string(4). string(5));
> }

With the newer "print" statements, this expression is no longer state of the
art.  How would this compare?

  printf("%d %d %d %d %d %d %d\n", get_tsc() /* we have that? */,
         get_cpu(), pid(), 1, 2, 3, 4, 5);

- FChE

Re: [SAMPLE][PATCH 1/3]BTI: Binary Transport Interface for SystemTap

[Masami Hiramatsu]

Hi, Frank

Frank Ch. Eigler wrote:
> hiramatu wrote:
>>[...]  The systemtap script with BTI (*1) has about 1.4 micro secs
>>of processing time. The systemtap script with ATI (*2) has about 4
>>micro secs of processing time. [...]
> 
>>(*2)
>>probe kernel.function("sys_gettimeofday") {
>>      log(string(get_tsc()) . string(get_cpu()) . string(pid()) . string(1)=
>> .
>>string(2). string(3). string(4). string(5));
>>}
> 
> With the newer "print" statements, this expression is no longer state of the
> art.  How would this compare?

OK. I measured the script using printf(). And the processing time is
about 2.6 micro secs. So, I expects BTI still has low overhead.

>   printf("%d %d %d %d %d %d %d\n", get_tsc() /* we have that? */,
>          get_cpu(), pid(), 1, 2, 3, 4, 5);

Oh, I forgot to write these functions. They are here:

function get_tsc:long () %{
        rdtscll(THIS->__retvalue);
%}
function get_cpu:long () %{
        THIS->__retvalue = smp_processor_id();
%}


-- 
Masami HIRAMATSU
2nd Research Dept.
Hitachi, Ltd., Systems Development Laboratory
E-mail: hiramatu@sdl.hitachi.co.jp