* [Qemu-devel] [RFC PATCH v3 0/3] simpletrace : support var num of args and strings.
@ 2012-01-10 10:59 Harsh Prateek Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
` (2 more replies)
0 siblings, 3 replies; 23+ messages in thread
From: Harsh Prateek Bora @ 2012-01-10 10:59 UTC (permalink / raw)
To: qemu-devel; +Cc: aneesh.kumar, mathieu.desnoyers, vilanova, stefanha
Existing simple trace can log upto 6 args per trace event and does not
support strings in trace record format. Introducing new trace format as
discussed earlier on list to support variable number/size of arguments.
(Ref: http://lists.gnu.org/archive/html/qemu-devel/2011-11/msg03426.html)
Basic testing of new tracelog format is successful. Stress testing not yet done.
Apply patches, then run:
make distclean
./configure with --enable-trace-backend=simple
make
sudo make install
Sample tracelog showing strings support:
[harsh@harshbora v9fs]$ scripts/simpletrace.py trace-events trace-23261
v9fs_version 0.000 tag=65535 id=100 msize=8192 version=9P2000.L
v9fs_version_return 17.530 tag=65535 id=100 msize=8192 version=9P2000.L
v9fs_attach 180.121 tag=1 id=104 fid=0 afid=18446744073709551615
uname=nobody aname=
Note: Other backends are only compile tested.
Version History:
v3:
- Added support for LTTng ust trace backend in tracetool.py
v2:
- Updated tracetool.py to support nop, stderr, dtrace backend
v1:
- Working protoype with tracetool.py converted only for simpletrace backend
Harsh Prateek Bora (3):
Converting tracetool.sh to tracetool.py
simpletrace-v2: Handle variable number/size of elements per trace
record.
simpletrace.py: updated log reader script to handle new log format
Makefile.objs | 6 +-
Makefile.target | 10 +-
configure | 7 +-
monitor.c | 2 +-
scripts/simpletrace.py | 109 ++++++++-
scripts/tracetool | 643 ------------------------------------------------
scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++
trace/simple.c | 178 +++++---------
trace/simple.h | 31 ++-
9 files changed, 783 insertions(+), 788 deletions(-)
delete mode 100755 scripts/tracetool
create mode 100755 scripts/tracetool.py
^ permalink raw reply [flat|nested] 23+ messages in thread
* [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 10:59 [Qemu-devel] [RFC PATCH v3 0/3] simpletrace : support var num of args and strings Harsh Prateek Bora
@ 2012-01-10 10:59 ` Harsh Prateek Bora
2012-01-10 14:50 ` Stefan Hajnoczi
` (3 more replies)
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record Harsh Prateek Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 3/3] simpletrace.py: updated log reader script to handle new log format Harsh Prateek Bora
2 siblings, 4 replies; 23+ messages in thread
From: Harsh Prateek Bora @ 2012-01-10 10:59 UTC (permalink / raw)
To: qemu-devel; +Cc: aneesh.kumar, mathieu.desnoyers, vilanova, stefanha
Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
Makefile.objs | 6 +-
Makefile.target | 10 +-
configure | 7 +-
scripts/tracetool | 643 --------------------------------------------------
scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
5 files changed, 597 insertions(+), 654 deletions(-)
delete mode 100755 scripts/tracetool
create mode 100755 scripts/tracetool.py
diff --git a/Makefile.objs b/Makefile.objs
index 804bc3c..984034a 100644
--- a/Makefile.objs
+++ b/Makefile.objs
@@ -344,12 +344,12 @@ else
trace.h: trace.h-timestamp
endif
trace.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/config-host.mak
- $(call quiet-command,sh $(SRC_PATH)/scripts/tracetool --$(TRACE_BACKEND) -h < $< > $@," GEN trace.h")
+ $(call quiet-command,$(PYTHON) $(SRC_PATH)/scripts/tracetool.py --backend=$(TRACE_BACKEND) -h < $< > $@," GEN trace.h")
@cmp -s $@ trace.h || cp $@ trace.h
trace.c: trace.c-timestamp
trace.c-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/config-host.mak
- $(call quiet-command,sh $(SRC_PATH)/scripts/tracetool --$(TRACE_BACKEND) -c < $< > $@," GEN trace.c")
+ $(call quiet-command,$(PYTHON) $(SRC_PATH)/scripts/tracetool.py --backend=$(TRACE_BACKEND) -c < $< > $@," GEN trace.c")
@cmp -s $@ trace.c || cp $@ trace.c
trace.o: trace.c $(GENERATED_HEADERS)
@@ -362,7 +362,7 @@ trace-dtrace.h: trace-dtrace.dtrace
# rule file. So we use '.dtrace' instead
trace-dtrace.dtrace: trace-dtrace.dtrace-timestamp
trace-dtrace.dtrace-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/config-host.mak
- $(call quiet-command,sh $(SRC_PATH)/scripts/tracetool --$(TRACE_BACKEND) -d < $< > $@," GEN trace-dtrace.dtrace")
+ $(call quiet-command,$(PYTHON) $(SRC_PATH)/scripts/tracetool.py --backend=$(TRACE_BACKEND) -d < $< > $@," GEN trace-dtrace.dtrace")
@cmp -s $@ trace-dtrace.dtrace || cp $@ trace-dtrace.dtrace
trace-dtrace.o: trace-dtrace.dtrace $(GENERATED_HEADERS)
diff --git a/Makefile.target b/Makefile.target
index 1e90df7..07b21d1 100644
--- a/Makefile.target
+++ b/Makefile.target
@@ -50,11 +50,11 @@ TARGET_TYPE=system
endif
$(QEMU_PROG).stp:
- $(call quiet-command,sh $(SRC_PATH)/scripts/tracetool \
- --$(TRACE_BACKEND) \
- --binary $(bindir)/$(QEMU_PROG) \
- --target-arch $(TARGET_ARCH) \
- --target-type $(TARGET_TYPE) \
+ $(call quiet-command,$(PYTHON) $(SRC_PATH)/scripts/tracetool.py \
+ --backend=$(TRACE_BACKEND) \
+ --binary=$(bindir)/$(QEMU_PROG) \
+ --target-arch=$(TARGET_ARCH) \
+ --target-type=$(TARGET_TYPE) \
--stap < $(SRC_PATH)/trace-events > $(QEMU_PROG).stp," GEN $(QEMU_PROG).stp")
else
stap:
diff --git a/configure b/configure
index 19e8394..40a18d8 100755
--- a/configure
+++ b/configure
@@ -1040,7 +1040,7 @@ echo " --disable-docs disable documentation build"
echo " --disable-vhost-net disable vhost-net acceleration support"
echo " --enable-vhost-net enable vhost-net acceleration support"
echo " --enable-trace-backend=B Set trace backend"
-echo " Available backends:" $("$source_path"/scripts/tracetool --list-backends)
+echo " Available backends:" $("$source_path"/scripts/tracetool.py --list-backends)
echo " --with-trace-file=NAME Full PATH,NAME of file to store traces"
echo " Default:trace-<pid>"
echo " --disable-spice disable spice"
@@ -2477,7 +2477,7 @@ fi
##########################################
# check if trace backend exists
-sh "$source_path/scripts/tracetool" "--$trace_backend" --check-backend > /dev/null 2> /dev/null
+$python "$source_path/scripts/tracetool.py" "--backend=$trace_backend" --check-backend > /dev/null 2> /dev/null
if test "$?" -ne 0 ; then
echo
echo "Error: invalid trace backend"
@@ -2495,7 +2495,8 @@ if test "$trace_backend" = "ust"; then
int main(void) { return 0; }
EOF
if compile_prog "" "" ; then
- LIBS="-lust $LIBS"
+ LIBS="-lust -lurcu-bp $LIBS"
+ libs_qga+="-lust -lurcu-bp"
else
echo
echo "Error: Trace backend 'ust' missing libust header files"
diff --git a/scripts/tracetool b/scripts/tracetool
deleted file mode 100755
index 4c9951d..0000000
--- a/scripts/tracetool
+++ /dev/null
@@ -1,643 +0,0 @@
-#!/bin/sh
-#
-# Code generator for trace events
-#
-# Copyright IBM, Corp. 2010
-#
-# This work is licensed under the terms of the GNU GPL, version 2. See
-# the COPYING file in the top-level directory.
-
-# Disable pathname expansion, makes processing text with '*' characters simpler
-set -f
-
-usage()
-{
- cat >&2 <<EOF
-usage: $0 [--nop | --simple | --stderr | --ust | --dtrace] [-h | -c]
-Generate tracing code for a file on stdin.
-
-Backends:
- --nop Tracing disabled
- --simple Simple built-in backend
- --stderr Stderr built-in backend
- --ust LTTng User Space Tracing backend
- --dtrace DTrace/SystemTAP backend
-
-Output formats:
- -h Generate .h file
- -c Generate .c file
- -d Generate .d file (DTrace only)
- --stap Generate .stp file (DTrace with SystemTAP only)
-
-Options:
- --binary [path] Full path to QEMU binary
- --target-arch [arch] QEMU emulator target arch
- --target-type [type] QEMU emulator target type ('system' or 'user')
- --probe-prefix [prefix] Prefix for dtrace probe names
- (default: qemu-\$targettype-\$targetarch)
-
-EOF
- exit 1
-}
-
-# Print a line without interpreting backslash escapes
-#
-# The built-in echo command may interpret backslash escapes without an option
-# to disable this behavior.
-puts()
-{
- printf "%s\n" "$1"
-}
-
-# Get the name of a trace event
-get_name()
-{
- local name
- name=${1%%\(*}
- echo "${name##* }"
-}
-
-# Get the given property of a trace event
-# 1: trace-events line
-# 2: property name
-# -> return 0 if property is present, or 1 otherwise
-has_property()
-{
- local props prop
- props=${1%%\(*}
- props=${props% *}
- for prop in $props; do
- if [ "$prop" = "$2" ]; then
- return 0
- fi
- done
- return 1
-}
-
-# Get the argument list of a trace event, including types and names
-get_args()
-{
- local args
- args=${1#*\(}
- args=${args%%\)*}
- echo "$args"
-}
-
-# Get the argument name list of a trace event
-get_argnames()
-{
- local nfields field name sep
- nfields=0
- sep="$2"
- for field in $(get_args "$1"); do
- nfields=$((nfields + 1))
-
- # Drop pointer star
- field=${field#\*}
-
- # Only argument names have commas at the end
- name=${field%,}
- test "$field" = "$name" && continue
-
- printf "%s%s " $name $sep
- done
-
- # Last argument name
- if [ "$nfields" -gt 1 ]
- then
- printf "%s" "$name"
- fi
-}
-
-# Get the number of arguments to a trace event
-get_argc()
-{
- local name argc
- argc=0
- for name in $(get_argnames "$1", ","); do
- argc=$((argc + 1))
- done
- echo $argc
-}
-
-# Get the format string including double quotes for a trace event
-get_fmt()
-{
- puts "${1#*)}"
-}
-
-linetoh_begin_nop()
-{
- return
-}
-
-linetoh_nop()
-{
- local name args
- name=$(get_name "$1")
- args=$(get_args "$1")
-
- # Define an empty function for the trace event
- cat <<EOF
-static inline void trace_$name($args)
-{
-}
-EOF
-}
-
-linetoh_end_nop()
-{
- return
-}
-
-linetoc_begin_nop()
-{
- return
-}
-
-linetoc_nop()
-{
- # No need for function definitions in nop backend
- return
-}
-
-linetoc_end_nop()
-{
- return
-}
-
-linetoh_begin_simple()
-{
- cat <<EOF
-#include "trace/simple.h"
-EOF
-
- simple_event_num=0
-}
-
-cast_args_to_uint64_t()
-{
- local arg
- for arg in $(get_argnames "$1", ","); do
- printf "%s" "(uint64_t)(uintptr_t)$arg"
- done
-}
-
-linetoh_simple()
-{
- local name args argc trace_args
- name=$(get_name "$1")
- args=$(get_args "$1")
- argc=$(get_argc "$1")
-
- trace_args="$simple_event_num"
- if [ "$argc" -gt 0 ]
- then
- trace_args="$trace_args, $(cast_args_to_uint64_t "$1")"
- fi
-
- cat <<EOF
-static inline void trace_$name($args)
-{
- trace$argc($trace_args);
-}
-EOF
-
- simple_event_num=$((simple_event_num + 1))
-}
-
-linetoh_end_simple()
-{
- cat <<EOF
-#define NR_TRACE_EVENTS $simple_event_num
-extern TraceEvent trace_list[NR_TRACE_EVENTS];
-EOF
-}
-
-linetoc_begin_simple()
-{
- cat <<EOF
-#include "trace.h"
-
-TraceEvent trace_list[] = {
-EOF
- simple_event_num=0
-
-}
-
-linetoc_simple()
-{
- local name
- name=$(get_name "$1")
- cat <<EOF
-{.tp_name = "$name", .state=0},
-EOF
- simple_event_num=$((simple_event_num + 1))
-}
-
-linetoc_end_simple()
-{
- cat <<EOF
-};
-EOF
-}
-
-#STDERR
-linetoh_begin_stderr()
-{
- cat <<EOF
-#include <stdio.h>
-#include "trace/stderr.h"
-
-extern TraceEvent trace_list[];
-EOF
-
- stderr_event_num=0
-}
-
-linetoh_stderr()
-{
- local name args argnames argc fmt
- name=$(get_name "$1")
- args=$(get_args "$1")
- argnames=$(get_argnames "$1" ",")
- argc=$(get_argc "$1")
- fmt=$(get_fmt "$1")
-
- if [ "$argc" -gt 0 ]; then
- argnames=", $argnames"
- fi
-
- cat <<EOF
-static inline void trace_$name($args)
-{
- if (trace_list[$stderr_event_num].state != 0) {
- fprintf(stderr, "$name " $fmt "\n" $argnames);
- }
-}
-EOF
- stderr_event_num=$((stderr_event_num + 1))
-
-}
-
-linetoh_end_stderr()
-{
- cat <<EOF
-#define NR_TRACE_EVENTS $stderr_event_num
-EOF
-}
-
-linetoc_begin_stderr()
-{
- cat <<EOF
-#include "trace.h"
-
-TraceEvent trace_list[] = {
-EOF
- stderr_event_num=0
-}
-
-linetoc_stderr()
-{
- local name
- name=$(get_name "$1")
- cat <<EOF
-{.tp_name = "$name", .state=0},
-EOF
- stderr_event_num=$(($stderr_event_num + 1))
-}
-
-linetoc_end_stderr()
-{
- cat <<EOF
-};
-EOF
-}
-#END OF STDERR
-
-# Clean up after UST headers which pollute the namespace
-ust_clean_namespace() {
- cat <<EOF
-#undef mutex_lock
-#undef mutex_unlock
-#undef inline
-#undef wmb
-EOF
-}
-
-linetoh_begin_ust()
-{
- echo "#include <ust/tracepoint.h>"
- ust_clean_namespace
-}
-
-linetoh_ust()
-{
- local name args argnames
- name=$(get_name "$1")
- args=$(get_args "$1")
- argnames=$(get_argnames "$1", ",")
-
- cat <<EOF
-DECLARE_TRACE(ust_$name, TP_PROTO($args), TP_ARGS($argnames));
-#define trace_$name trace_ust_$name
-EOF
-}
-
-linetoh_end_ust()
-{
- return
-}
-
-linetoc_begin_ust()
-{
- cat <<EOF
-#include <ust/marker.h>
-$(ust_clean_namespace)
-#include "trace.h"
-EOF
-}
-
-linetoc_ust()
-{
- local name args argnames fmt
- name=$(get_name "$1")
- args=$(get_args "$1")
- argnames=$(get_argnames "$1", ",")
- [ -z "$argnames" ] || argnames=", $argnames"
- fmt=$(get_fmt "$1")
-
- cat <<EOF
-DEFINE_TRACE(ust_$name);
-
-static void ust_${name}_probe($args)
-{
- trace_mark(ust, $name, $fmt$argnames);
-}
-EOF
-
- # Collect names for later
- names="$names $name"
-}
-
-linetoc_end_ust()
-{
- cat <<EOF
-static void __attribute__((constructor)) trace_init(void)
-{
-EOF
-
- for name in $names; do
- cat <<EOF
- register_trace_ust_$name(ust_${name}_probe);
-EOF
- done
-
- echo "}"
-}
-
-linetoh_begin_dtrace()
-{
- cat <<EOF
-#include "trace-dtrace.h"
-EOF
-}
-
-linetoh_dtrace()
-{
- local name args argnames nameupper
- name=$(get_name "$1")
- args=$(get_args "$1")
- argnames=$(get_argnames "$1", ",")
-
- nameupper=`echo $name | tr '[:lower:]' '[:upper:]'`
-
- # Define an empty function for the trace event
- cat <<EOF
-static inline void trace_$name($args) {
- if (QEMU_${nameupper}_ENABLED()) {
- QEMU_${nameupper}($argnames);
- }
-}
-EOF
-}
-
-linetoh_end_dtrace()
-{
- return
-}
-
-linetoc_begin_dtrace()
-{
- return
-}
-
-linetoc_dtrace()
-{
- # No need for function definitions in dtrace backend
- return
-}
-
-linetoc_end_dtrace()
-{
- return
-}
-
-linetod_begin_dtrace()
-{
- cat <<EOF
-provider qemu {
-EOF
-}
-
-linetod_dtrace()
-{
- local name args
- name=$(get_name "$1")
- args=$(get_args "$1")
-
- # DTrace provider syntax expects foo() for empty
- # params, not foo(void)
- if [ "$args" = "void" ]; then
- args=""
- fi
-
- # Define prototype for probe arguments
- cat <<EOF
- probe $name($args);
-EOF
-}
-
-linetod_end_dtrace()
-{
- cat <<EOF
-};
-EOF
-}
-
-linetostap_begin_dtrace()
-{
- return
-}
-
-linetostap_dtrace()
-{
- local i arg name args arglist
- name=$(get_name "$1")
- args=$(get_args "$1")
- arglist=$(get_argnames "$1", "")
-
- # Define prototype for probe arguments
- cat <<EOF
-probe $probeprefix.$name = process("$binary").mark("$name")
-{
-EOF
-
- i=1
- for arg in $arglist
- do
- # 'limit' is a reserved keyword
- if [ "$arg" = "limit" ]; then
- arg="_limit"
- fi
- cat <<EOF
- $arg = \$arg$i;
-EOF
- i="$((i+1))"
- done
-
- cat <<EOF
-}
-EOF
-}
-
-linetostap_end_dtrace()
-{
- return
-}
-
-# Process stdin by calling begin, line, and end functions for the backend
-convert()
-{
- local begin process_line end str disable
- begin="lineto$1_begin_$backend"
- process_line="lineto$1_$backend"
- end="lineto$1_end_$backend"
-
- "$begin"
-
- while read -r str; do
- # Skip comments and empty lines
- test -z "${str%%#*}" && continue
-
- echo
- # Process the line. The nop backend handles disabled lines.
- if has_property "$str" "disable"; then
- "lineto$1_nop" "$str"
- else
- "$process_line" "$str"
- fi
- done
-
- echo
- "$end"
-}
-
-tracetoh()
-{
- cat <<EOF
-#ifndef TRACE_H
-#define TRACE_H
-
-/* This file is autogenerated by tracetool, do not edit. */
-
-#include "qemu-common.h"
-EOF
- convert h
- echo "#endif /* TRACE_H */"
-}
-
-tracetoc()
-{
- echo "/* This file is autogenerated by tracetool, do not edit. */"
- convert c
-}
-
-tracetod()
-{
- if [ $backend != "dtrace" ]; then
- echo "DTrace probe generator not applicable to $backend backend"
- exit 1
- fi
- echo "/* This file is autogenerated by tracetool, do not edit. */"
- convert d
-}
-
-tracetostap()
-{
- if [ $backend != "dtrace" ]; then
- echo "SystemTAP tapset generator not applicable to $backend backend"
- exit 1
- fi
- if [ -z "$binary" ]; then
- echo "--binary is required for SystemTAP tapset generator"
- exit 1
- fi
- if [ -z "$probeprefix" -a -z "$targettype" ]; then
- echo "--target-type is required for SystemTAP tapset generator"
- exit 1
- fi
- if [ -z "$probeprefix" -a -z "$targetarch" ]; then
- echo "--target-arch is required for SystemTAP tapset generator"
- exit 1
- fi
- if [ -z "$probeprefix" ]; then
- probeprefix="qemu.$targettype.$targetarch";
- fi
- echo "/* This file is autogenerated by tracetool, do not edit. */"
- convert stap
-}
-
-
-backend=
-output=
-binary=
-targettype=
-targetarch=
-probeprefix=
-
-
-until [ -z "$1" ]
-do
- case "$1" in
- "--nop" | "--simple" | "--stderr" | "--ust" | "--dtrace") backend="${1#--}" ;;
-
- "--binary") shift ; binary="$1" ;;
- "--target-arch") shift ; targetarch="$1" ;;
- "--target-type") shift ; targettype="$1" ;;
- "--probe-prefix") shift ; probeprefix="$1" ;;
-
- "-h" | "-c" | "-d") output="${1#-}" ;;
- "--stap") output="${1#--}" ;;
-
- "--check-backend") exit 0 ;; # used by ./configure to test for backend
-
- "--list-backends") # used by ./configure to list available backends
- echo "nop simple stderr ust dtrace"
- exit 0
- ;;
-
- *)
- usage;;
- esac
- shift
-done
-
-if [ "$backend" = "" -o "$output" = "" ]; then
- usage
-fi
-
-gen="traceto$output"
-"$gen"
-
-exit 0
diff --git a/scripts/tracetool.py b/scripts/tracetool.py
new file mode 100755
index 0000000..6874f66
--- /dev/null
+++ b/scripts/tracetool.py
@@ -0,0 +1,585 @@
+#!/usr/bin/env python
+# Python based tracetool script (Code generator for trace events)
+#
+# Copyright IBM, Corp. 2011
+#
+# This work is licensed under the terms of the GNU GPL, version 2. See
+# the COPYING file in the top-level directory.
+#
+#
+
+import sys
+import getopt
+
+def usage():
+ print "Tracetool: Generate tracing code for trace events file on stdin"
+ print "Usage:"
+ print sys.argv[0], " --backend=[nop|simple|stderr|dtrace|ust] [-h|-c|-d|--stap]"
+ print '''
+Backends:
+ --nop Tracing disabled
+ --simple Simple built-in backend
+ --stderr Stderr built-in backend
+ --dtrace DTrace/SystemTAP backend
+ --ust LTTng User Space Tracing backend
+
+Output formats:
+ -h Generate .h file
+ -c Generate .c file
+ -d Generate .d file (DTrace only)
+ --stap Generate .stp file (DTrace with SystemTAP only)
+
+Options:
+ --binary [path] Full path to QEMU binary
+ --target-arch [arch] QEMU emulator target arch
+ --target-type [type] QEMU emulator target type ('system' or 'user')
+ --probe-prefix [prefix] Prefix for dtrace probe names
+ (default: qemu-targettype-targetarch)
+'''
+ sys.exit(1)
+
+def get_name(line, sep='('):
+ head, sep, tail = line.partition(sep)
+ return head
+
+def get_args(line, sep1='(', sep2=')'):
+ head, sep1, tail = line.partition(sep1)
+ args, sep2, fmt_str = tail.partition(sep2)
+ return args
+
+def get_argnames(line, sep=','):
+ nfields = 0
+ str = []
+ args = get_args(line)
+ for field in args.split():
+ nfields = nfields + 1
+ # Drop pointer star
+ type, ptr, tail = field.partition('*')
+ if type != field:
+ field = tail
+
+ name, sep, tail = field.partition(',')
+
+ if name == field:
+ continue
+ str.append(name)
+ str.append(", ")
+
+ if nfields > 1:
+ str.append(name)
+ return ''.join(str)
+ else:
+ return ''
+
+def get_argc(line):
+ argc = 0
+ argnames = get_argnames(line)
+ if argnames:
+ for name in argnames.split(','):
+ argc = argc + 1
+ return argc
+
+def get_fmt(line, sep=')'):
+ event, sep, fmt = line.partition(sep)
+ return fmt
+
+def calc_sizeofargs(line):
+ args = get_args(line)
+ argc = get_argc(line)
+ strtype = ('const char*', 'char*', 'const char *', 'char *')
+ str = []
+ newstr = ""
+ if argc > 0:
+ str = args.split(',')
+ for elem in str:
+ if elem.lstrip().startswith(strtype): #strings
+ type, sep, var = elem.rpartition('*')
+ newstr = newstr+"4 + strlen("+var.lstrip()+") + "
+ #elif '*' in elem:
+ # newstr = newstr + "4 + " # pointer vars
+ else:
+ #type, sep, var = elem.rpartition(' ')
+ #newstr = newstr+"sizeof("+type.lstrip()+") + "
+ newstr = newstr + '8 + '
+ newstr = newstr + '0' # for last +
+ return newstr
+
+
+def trace_h_begin():
+ print '''#ifndef TRACE_H
+#define TRACE_H
+
+/* This file is autogenerated by tracetool, do not edit. */
+
+#include "qemu-common.h"'''
+ return
+
+def trace_h_end():
+ print '#endif /* TRACE_H */'
+ return
+
+def trace_c_begin():
+ print '/* This file is autogenerated by tracetool, do not edit. */'
+ return
+
+def trace_c_end():
+ # nop, required for trace_gen
+ return
+
+def nop_h(events):
+ print
+ for event in events:
+ print '''static inline void trace_%(name)s(%(args)s)
+{
+}
+''' % {
+ 'name': event.name,
+ 'args': event.args
+}
+ return
+
+def nop_c(events):
+ # nop, reqd for converters
+ return
+
+
+def simple_h(events):
+ print '#include "trace/simple.h"'
+ print
+ for event in events:
+ print 'void trace_%(name)s(%(args)s);' % {
+ 'name': event.name,
+ 'args': event.args
+}
+ print
+ print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
+ print 'extern TraceEvent trace_list[NR_TRACE_EVENTS];'
+
+ return
+
+def is_string(arg):
+ strtype = ('const char*', 'char*', 'const char *', 'char *')
+ if arg.lstrip().startswith(strtype):
+ return True
+ else:
+ return False
+
+def simple_c(events):
+ rec_off = 0
+ print '#include "trace.h"'
+ print '#include "trace/simple.h"'
+ print
+ print 'TraceEvent trace_list[] = {'
+ print
+ eventlist = list(events)
+ for event in eventlist:
+ print '{.tp_name = "%(name)s", .state=0},' % {
+ 'name': event.name
+}
+ print
+ print '};'
+ print
+ for event in eventlist:
+ argc = event.argc
+ print '''void trace_%(name)s(%(args)s)
+{
+ unsigned int tbuf_idx, rec_off;
+ uint64_t var64 __attribute__ ((unused));
+ uint64_t pvar64 __attribute__ ((unused));
+ uint32_t slen __attribute__ ((unused));
+
+ if (!trace_list[%(event_id)s].state) {
+ return;
+ }
+''' % {
+ 'name': event.name,
+ 'args': event.args,
+ 'event_id': event.num,
+}
+ print '''
+ tbuf_idx = trace_alloc_record(%(event_id)s, %(sizestr)s);
+ rec_off = (tbuf_idx + ST_V2_REC_HDR_LEN) %% TRACE_BUF_LEN; /* seek record header */
+''' % {'event_id': event.num, 'sizestr': event.sizestr,}
+
+ if argc > 0:
+ str = event.arglist
+ for elem in str:
+ if is_string(elem): # if string
+ type, sep, var = elem.rpartition('*')
+ print '''
+ slen = strlen(%(var)s);
+ write_to_buffer(rec_off, (uint8_t*)&slen, sizeof(slen));
+ rec_off += sizeof(slen);''' % {
+ 'var': var.lstrip()
+}
+ print '''
+ write_to_buffer(rec_off, (uint8_t*)%(var)s, slen);
+ rec_off += slen;''' % {
+ 'var': var.lstrip()
+}
+ elif '*' in elem: # pointer var (not string)
+ type, sep, var = elem.rpartition('*')
+ print '''
+ pvar64 = (uint64_t)(uint64_t*)%(var)s;
+ write_to_buffer(rec_off, (uint8_t*)&pvar64, sizeof(uint64_t));
+ rec_off += sizeof(uint64_t);''' % {
+ 'var': var.lstrip()
+}
+ else: # primitive data type
+ type, sep, var = elem.rpartition(' ')
+ print '''
+ var64 = (uint64_t)%(var)s;
+ write_to_buffer(rec_off, (uint8_t*)&var64, sizeof(uint64_t));
+ rec_off += sizeof(uint64_t);''' % {
+ 'var': var.lstrip()
+}
+ print '''
+ trace_mark_record_complete(tbuf_idx);'''
+ print '}'
+ print
+
+ return
+
+def stderr_h(events):
+ print '''#include <stdio.h>
+#include "trace/stderr.h"
+
+extern TraceEvent trace_list[];'''
+ for event in events:
+ argnames = event.argnames
+ if event.argc > 0:
+ argnames = ', ' + event.argnames
+ else:
+ argnames = ''
+ print '''
+static inline void trace_%(name)s(%(args)s)
+{
+ if (trace_list[%(event_num)s].state != 0) {
+ fprintf(stderr, "%(name)s " %(fmt)s "\\n" %(argnames)s);
+ }
+}''' % {
+ 'name': event.name,
+ 'args': event.args,
+ 'event_num': event.num,
+ 'fmt': event.fmt.rstrip('\n'),
+ 'argnames': argnames
+}
+ print
+ print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
+
+def stderr_c(events):
+ print '''#include "trace.h"
+
+TraceEvent trace_list[] = {
+'''
+ for event in events:
+ print '{.tp_name = "%(name)s", .state=0},' % {
+ 'name': event.name
+}
+ print
+ print '};'
+
+def ust_h(events):
+ print '''#include <ust/tracepoint.h>
+#undef mutex_lock
+#undef mutex_unlock
+#undef inline
+#undef wmb'''
+
+ for event in events:
+ if event.argc > 0:
+ print '''
+DECLARE_TRACE(ust_%(name)s, TP_PROTO(%(args)s), TP_ARGS(%(argnames)s));
+#define trace_%(name)s trace_ust_%(name)s''' % {
+ 'name': event.name,
+ 'args': event.args,
+ 'argnames': event.argnames
+}
+ else:
+ print '''
+_DECLARE_TRACEPOINT_NOARGS(ust_%(name)s);
+#define trace_%(name)s trace_ust_%(name)s''' % {
+ 'name': event.name,
+}
+ print
+ return
+
+def ust_c(events):
+ print '''#include <ust/marker.h>
+#undef mutex_lock
+#undef mutex_unlock
+#undef inline
+#undef wmb
+#include "trace.h"'''
+ eventlist = list(events)
+ for event in eventlist:
+ argnames = event.argnames
+ if event.argc > 0:
+ argnames = ', ' + event.argnames
+ print '''
+DEFINE_TRACE(ust_%(name)s);
+
+static void ust_%(name)s_probe(%(args)s)
+{
+ trace_mark(ust, %(name)s, %(fmt)s%(argnames)s);
+}''' % {
+ 'name': event.name,
+ 'args': event.args,
+ 'fmt': event.fmt.rstrip('\n'),
+ 'argnames': argnames
+}
+ else:
+ print '''
+DEFINE_TRACE(ust_%(name)s);
+
+static void ust_%(name)s_probe(%(args)s)
+{
+ trace_mark(ust, %(name)s, UST_MARKER_NOARGS);
+}''' % {
+ 'name': event.name,
+ 'args': event.args,
+}
+
+ # register probes
+ print '''
+static void __attribute__((constructor)) trace_init(void)
+{'''
+ for event in eventlist:
+ print ' register_trace_ust_%(name)s(ust_%(name)s_probe);' % {
+ 'name': event.name
+}
+ print '}'
+
+ return
+
+def dtrace_h(events):
+ print '#include "trace-dtrace.h"'
+ print
+ for event in events:
+ print '''static inline void trace_%(name)s(%(args)s) {
+ if (QEMU_%(uppername)s_ENABLED()) {
+ QEMU_%(uppername)s(%(argnames)s);
+ }
+}
+''' % {
+ 'name': event.name,
+ 'args': event.args,
+ 'uppername': event.name.upper(),
+ 'argnames': event.argnames,
+}
+
+def dtrace_c(events):
+ return # No need for function definitions in dtrace backend
+
+def dtrace_d(events):
+ print 'provider qemu {'
+ for event in events:
+ args = event.args
+
+ # DTrace provider syntax expects foo() for empty
+ # params, not foo(void)
+ if args == 'void':
+ args = ''
+
+ # Define prototype for probe arguments
+ print '''
+ probe %(name)s(%(args)s);''' % {
+ 'name': event.name,
+ 'args': args
+}
+ print
+ print '};'
+ return
+
+def dtrace_stp(events):
+ for event in events:
+ # Define prototype for probe arguments
+ print '''
+probe %(probeprefix)s.%(name)s = process("%(binary)s").mark("%(name)s")
+{''' % {
+ 'probeprefix': probeprefix,
+ 'name': event.name,
+ 'binary': binary
+}
+ i = 1
+ if event.argc > 0:
+ for arg in event.argnames.split(','):
+ # 'limit' is a reserved keyword
+ if arg == 'limit':
+ arg = '_limit'
+ print ' %s = $arg%d;' % (arg.lstrip(), i)
+ i += 1
+ print '}'
+ print
+ return
+
+def trace_stap_begin():
+ global probeprefix
+ if backend != "dtrace":
+ print 'SystemTAP tapset generator not applicable to %s backend' % backend
+ sys.exit(1)
+ if binary == "":
+ print '--binary is required for SystemTAP tapset generator'
+ sys.exit(1)
+ if ((probeprefix == "") and (targettype == "")):
+ print '--target-type is required for SystemTAP tapset generator'
+ sys.exit(1)
+ if ((probeprefix == "") and (targetarch == "")):
+ print '--target-arch is required for SystemTAP tapset generator'
+ sys.exit(1)
+ if probeprefix == "":
+ probeprefix = 'qemu.' + targettype + '.' + targetarch
+ print '/* This file is autogenerated by tracetool, do not edit. */'
+ return
+
+def trace_stap_end():
+ return #nop, reqd for trace_gen
+
+def trace_d_begin():
+ if backend != 'dtrace':
+ print 'DTrace probe generator not applicable to %s backend' % backend
+ sys.exit(1)
+ print '/* This file is autogenerated by tracetool, do not edit. */'
+
+def trace_d_end():
+ return #nop, reqd for trace_gen
+
+
+# Registry of backends and their converter functions
+converters = {
+ 'simple': {
+ 'h': simple_h,
+ 'c': simple_c,
+ },
+
+ 'nop': {
+ 'h': nop_h,
+ 'c': nop_c,
+ },
+
+ 'stderr': {
+ 'h': stderr_h,
+ 'c': stderr_c,
+ },
+
+ 'dtrace': {
+ 'h': dtrace_h,
+ 'c': dtrace_c,
+ 'd': dtrace_d,
+ 'stap': dtrace_stp
+ },
+
+ 'ust': {
+ 'h': ust_h,
+ 'c': ust_c,
+ },
+
+}
+
+# Trace file header and footer code generators
+trace_gen = {
+ 'h': {
+ 'begin': trace_h_begin,
+ 'end': trace_h_end,
+ },
+ 'c': {
+ 'begin': trace_c_begin,
+ 'end': trace_c_end,
+ },
+ 'd': {
+ 'begin': trace_d_begin,
+ 'end': trace_d_end,
+ },
+ 'stap': {
+ 'begin': trace_stap_begin,
+ 'end': trace_stap_end,
+ },
+}
+
+# A trace event
+class Event(object):
+ def __init__(self, num, line):
+ self.num = num
+ self.args = get_args(line)
+ self.arglist = self.args.split(',')
+ self.name = get_name(line)
+ self.argc = get_argc(line)
+ self.argnames = get_argnames(line)
+ self.sizestr = calc_sizeofargs(line)
+ self.fmt = get_fmt(line)
+
+# Generator that yields Event objects given a trace-events file object
+def read_events(fobj):
+ event_num = 0
+ for line in fobj:
+ if not line.strip():
+ continue
+ if line.lstrip().startswith('#'):
+ continue
+ yield Event(event_num, line)
+ event_num += 1
+
+backend = ""
+output = ""
+binary = ""
+targettype = ""
+targetarch = ""
+probeprefix = ""
+
+def main():
+ global backend, output, binary, targettype, targetarch, probeprefix
+ supported_backends = ["simple", "nop", "stderr", "dtrace", "ust"]
+ short_options = "hcd"
+ long_options = ["stap", "backend=", "binary=", "target-arch=", "target-type=", "probe-prefix=", "list-backends", "check-backend"]
+ try:
+ opts, args = getopt.getopt(sys.argv[1:], short_options, long_options)
+ except getopt.GetoptError, err:
+ # print help information and exit:
+ print str(err) # will print something like "option -a not recognized"
+ usage()
+ sys.exit(2)
+ for opt, arg in opts:
+ if opt == '-h':
+ output = 'h'
+ elif opt == '-c':
+ output = 'c'
+ elif opt == '-d':
+ output = 'd'
+ elif opt == '--stap':
+ output = 'stap'
+ elif opt == '--backend':
+ backend = arg
+ elif opt == '--binary':
+ binary = arg
+ elif opt == '--target-arch':
+ targetarch = arg
+ elif opt == '--target-type':
+ targettype = arg
+ elif opt == '--probe-prefix':
+ probeprefix = arg
+ elif opt == '--list-backends':
+ print 'simple, nop, stderr, dtrace'
+ sys.exit(0)
+ elif opt == "--check-backend":
+ if any(backend in s for s in supported_backends):
+ sys.exit(0)
+ else:
+ sys.exit(1)
+ else:
+ #assert False, "unhandled option"
+ print "unhandled option: ", opt
+ usage()
+
+ if backend == "" or output == "":
+ usage()
+ sys.exit(0)
+
+ events = read_events(sys.stdin)
+ trace_gen[output]['begin']()
+ converters[backend][output](events)
+ trace_gen[output]['end']()
+ return
+
+if __name__ == "__main__":
+ main()
+
--
1.7.1.1
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-10 10:59 [Qemu-devel] [RFC PATCH v3 0/3] simpletrace : support var num of args and strings Harsh Prateek Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
@ 2012-01-10 10:59 ` Harsh Prateek Bora
2012-01-10 16:41 ` Stefan Hajnoczi
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 3/3] simpletrace.py: updated log reader script to handle new log format Harsh Prateek Bora
2 siblings, 1 reply; 23+ messages in thread
From: Harsh Prateek Bora @ 2012-01-10 10:59 UTC (permalink / raw)
To: qemu-devel; +Cc: aneesh.kumar, mathieu.desnoyers, vilanova, stefanha
Advantages over existing simpletrace backend:
- More than 6 elements (vitually unlimited) arguments can be traced.
- This allows to trace strings (variable size element) as well.
Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
monitor.c | 2 +-
trace/simple.c | 178 ++++++++++++++++++++------------------------------------
trace/simple.h | 31 ++++++++--
3 files changed, 88 insertions(+), 123 deletions(-)
diff --git a/monitor.c b/monitor.c
index ffda0fe..b6f85d1 100644
--- a/monitor.c
+++ b/monitor.c
@@ -945,7 +945,7 @@ static void do_info_cpu_stats(Monitor *mon)
#if defined(CONFIG_TRACE_SIMPLE)
static void do_info_trace(Monitor *mon)
{
- st_print_trace((FILE *)mon, &monitor_fprintf);
+ /* FIXME: st_print_trace((FILE *)mon, &monitor_fprintf); */
}
#endif
diff --git a/trace/simple.c b/trace/simple.c
index b639dda..65cafe2 100644
--- a/trace/simple.c
+++ b/trace/simple.c
@@ -27,7 +27,7 @@
#define HEADER_MAGIC 0xf2b177cb0aa429b4ULL
/** Trace file version number, bump if format changes */
-#define HEADER_VERSION 0
+#define HEADER_VERSION 2
/** Records were dropped event ID */
#define DROPPED_EVENT_ID (~(uint64_t)0 - 1)
@@ -35,23 +35,6 @@
/** Trace record is valid */
#define TRACE_RECORD_VALID ((uint64_t)1 << 63)
-/** Trace buffer entry */
-typedef struct {
- uint64_t event;
- uint64_t timestamp_ns;
- uint64_t x1;
- uint64_t x2;
- uint64_t x3;
- uint64_t x4;
- uint64_t x5;
- uint64_t x6;
-} TraceRecord;
-
-enum {
- TRACE_BUF_LEN = 4096,
- TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
-};
-
/*
* Trace records are written out by a dedicated thread. The thread waits for
* records to become available, writes them out, and then waits again.
@@ -62,11 +45,12 @@ static GCond *trace_empty_cond;
static bool trace_available;
static bool trace_writeout_enabled;
-static TraceRecord trace_buf[TRACE_BUF_LEN];
+uint8_t trace_buf[TRACE_BUF_LEN];
static unsigned int trace_idx;
static FILE *trace_fp;
static char *trace_file_name = NULL;
+
/**
* Read a trace record from the trace buffer
*
@@ -75,16 +59,19 @@ static char *trace_file_name = NULL;
*
* Returns false if the record is not valid.
*/
-static bool get_trace_record(unsigned int idx, TraceRecord *record)
+static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
{
- if (!(trace_buf[idx].event & TRACE_RECORD_VALID)) {
+ TraceRecord *record = (TraceRecord *) &trace_buf[idx];
+ if (!(record->event & TRACE_RECORD_VALID)) {
return false;
}
__sync_synchronize(); /* read memory barrier before accessing record */
- *record = trace_buf[idx];
- record->event &= ~TRACE_RECORD_VALID;
+ *recordptr = g_malloc(record->length);
+ /* make a copy of record to avoid being overwritten */
+ memcpy(*recordptr, record, record->length);
+ (*recordptr)->event &= ~TRACE_RECORD_VALID;
return true;
}
@@ -106,6 +93,47 @@ static void flush_trace_file(bool wait)
g_static_mutex_unlock(&trace_lock);
}
+unsigned int trace_alloc_record(TraceEventID event, uint32_t datasize)
+{
+ unsigned int idx, rec_off;
+ uint32_t rec_len = ST_V2_REC_HDR_LEN + datasize;
+ uint64_t timestamp_ns = get_clock();
+
+ idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) % TRACE_BUF_LEN;
+ rec_off = idx;
+ write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
+ rec_off += sizeof(event);
+ write_to_buffer(rec_off, (uint8_t*)×tamp_ns, sizeof(timestamp_ns));
+ rec_off += sizeof(timestamp_ns);
+ write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len));
+ rec_off += sizeof(rec_len);
+ return idx;
+}
+
+void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size)
+{
+ uint32_t x = 0;
+ while (x < size)
+ {
+ if (idx >= TRACE_BUF_LEN) {
+ idx = idx % TRACE_BUF_LEN;
+ }
+ trace_buf[idx++] = dataptr[x++];
+ }
+}
+
+void trace_mark_record_complete(unsigned int idx)
+{
+ TraceRecord *record = (TraceRecord*) &trace_buf[idx];
+
+ __sync_synchronize(); /* write barrier before marking as valid */
+ record->event |= TRACE_RECORD_VALID;
+
+ if (idx > TRACE_BUF_FLUSH_THRESHOLD) {
+ flush_trace_file(false);
+ }
+}
+
static void wait_for_trace_records_available(void)
{
g_static_mutex_lock(&trace_lock);
@@ -120,7 +148,7 @@ static void wait_for_trace_records_available(void)
static gpointer writeout_thread(gpointer opaque)
{
- TraceRecord record;
+ TraceRecord record, *recordptr;
unsigned int writeout_idx = 0;
unsigned int num_available, idx;
size_t unused __attribute__ ((unused));
@@ -130,19 +158,20 @@ static gpointer writeout_thread(gpointer opaque)
num_available = trace_idx - writeout_idx;
if (num_available > TRACE_BUF_LEN) {
- record = (TraceRecord){
- .event = DROPPED_EVENT_ID,
- .x1 = num_available,
- };
- unused = fwrite(&record, sizeof(record), 1, trace_fp);
+ record.event = DROPPED_EVENT_ID,
+ record.length = num_available,
+ unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
writeout_idx += num_available;
}
idx = writeout_idx % TRACE_BUF_LEN;
- while (get_trace_record(idx, &record)) {
- trace_buf[idx].event = 0; /* clear valid bit */
- unused = fwrite(&record, sizeof(record), 1, trace_fp);
- idx = ++writeout_idx % TRACE_BUF_LEN;
+ while (get_trace_record(idx, &recordptr)) {
+ unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
+ writeout_idx += recordptr->length;
+ g_free(recordptr);
+ recordptr = (TraceRecord *) &trace_buf[idx];
+ recordptr->event = 0;
+ idx = writeout_idx % TRACE_BUF_LEN;
}
fflush(trace_fp);
@@ -150,71 +179,7 @@ static gpointer writeout_thread(gpointer opaque)
return NULL;
}
-static void trace(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3,
- uint64_t x4, uint64_t x5, uint64_t x6)
-{
- unsigned int idx;
- uint64_t timestamp;
-
- if (!trace_list[event].state) {
- return;
- }
-
- timestamp = get_clock();
-
- idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, 1) % TRACE_BUF_LEN;
- trace_buf[idx] = (TraceRecord){
- .event = event,
- .timestamp_ns = timestamp,
- .x1 = x1,
- .x2 = x2,
- .x3 = x3,
- .x4 = x4,
- .x5 = x5,
- .x6 = x6,
- };
- __sync_synchronize(); /* write barrier before marking as valid */
- trace_buf[idx].event |= TRACE_RECORD_VALID;
-
- if ((idx + 1) % TRACE_BUF_FLUSH_THRESHOLD == 0) {
- flush_trace_file(false);
- }
-}
-
-void trace0(TraceEventID event)
-{
- trace(event, 0, 0, 0, 0, 0, 0);
-}
-
-void trace1(TraceEventID event, uint64_t x1)
-{
- trace(event, x1, 0, 0, 0, 0, 0);
-}
-
-void trace2(TraceEventID event, uint64_t x1, uint64_t x2)
-{
- trace(event, x1, x2, 0, 0, 0, 0);
-}
-void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3)
-{
- trace(event, x1, x2, x3, 0, 0, 0);
-}
-
-void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4)
-{
- trace(event, x1, x2, x3, x4, 0, 0);
-}
-
-void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5)
-{
- trace(event, x1, x2, x3, x4, x5, 0);
-}
-
-void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6)
-{
- trace(event, x1, x2, x3, x4, x5, x6);
-}
void st_set_trace_file_enabled(bool enable)
{
@@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
static const TraceRecord header = {
.event = HEADER_EVENT_ID,
.timestamp_ns = HEADER_MAGIC,
- .x1 = HEADER_VERSION,
+ .length = HEADER_VERSION,
};
trace_fp = fopen(trace_file_name, "wb");
@@ -288,23 +253,6 @@ void st_print_trace_file_status(FILE *stream, int (*stream_printf)(FILE *stream,
trace_file_name, trace_fp ? "on" : "off");
}
-void st_print_trace(FILE *stream, int (*stream_printf)(FILE *stream, const char *fmt, ...))
-{
- unsigned int i;
-
- for (i = 0; i < TRACE_BUF_LEN; i++) {
- TraceRecord record;
-
- if (!get_trace_record(i, &record)) {
- continue;
- }
- stream_printf(stream, "Event %" PRIu64 " : %" PRIx64 " %" PRIx64
- " %" PRIx64 " %" PRIx64 " %" PRIx64 " %" PRIx64 "\n",
- record.event, record.x1, record.x2,
- record.x3, record.x4, record.x5,
- record.x6);
- }
-}
void st_flush_trace_buffer(void)
{
diff --git a/trace/simple.h b/trace/simple.h
index 466e75b..671cbeb 100644
--- a/trace/simple.h
+++ b/trace/simple.h
@@ -22,17 +22,34 @@ typedef struct {
bool state;
} TraceEvent;
-void trace0(TraceEventID event);
-void trace1(TraceEventID event, uint64_t x1);
-void trace2(TraceEventID event, uint64_t x1, uint64_t x2);
-void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3);
-void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4);
-void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5);
-void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6);
void st_print_trace(FILE *stream, fprintf_function stream_printf);
void st_print_trace_file_status(FILE *stream, fprintf_function stream_printf);
void st_set_trace_file_enabled(bool enable);
bool st_set_trace_file(const char *file);
void st_flush_trace_buffer(void);
+/* Interfaces for simpletrace v2 */
+
+/** Trace buffer entry */
+typedef struct {
+ uint64_t event; /* TraceEventID */
+ uint64_t timestamp_ns;
+ uint32_t length; /* in bytes */
+ uint32_t reserved; /* unused */
+ uint8_t arguments[]; /* arguments position affects ST_V2_REC_HDR_LEN */
+} TraceRecord;
+
+#define ST_V2_REC_HDR_LEN 24
+
+enum {
+ TRACE_BUF_LEN = 4096 * 64,
+ TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
+};
+
+extern uint8_t trace_buf[TRACE_BUF_LEN];
+
+unsigned int trace_alloc_record(TraceEventID event, uint32_t datasize);
+void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size);
+void trace_mark_record_complete(unsigned int idx);
+
#endif /* TRACE_SIMPLE_H */
--
1.7.1.1
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [Qemu-devel] [RFC PATCH v3 3/3] simpletrace.py: updated log reader script to handle new log format
2012-01-10 10:59 [Qemu-devel] [RFC PATCH v3 0/3] simpletrace : support var num of args and strings Harsh Prateek Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record Harsh Prateek Bora
@ 2012-01-10 10:59 ` Harsh Prateek Bora
2012-01-11 12:30 ` Stefan Hajnoczi
2 siblings, 1 reply; 23+ messages in thread
From: Harsh Prateek Bora @ 2012-01-10 10:59 UTC (permalink / raw)
To: qemu-devel; +Cc: aneesh.kumar, mathieu.desnoyers, vilanova, stefanha
Note: This script has been updated with minimal changes required to observe
the new trace log format in action and therefore can be improved for a
better design. It can still read the logs from older log format as well.
Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
---
scripts/simpletrace.py | 109 +++++++++++++++++++++++++++++++++++++++++++-----
1 files changed, 98 insertions(+), 11 deletions(-)
diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index f55e5e6..503b1b5 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -12,16 +12,37 @@
import struct
import re
import inspect
+import sys
+from tracetool import *
header_event_id = 0xffffffffffffffff
header_magic = 0xf2b177cb0aa429b4
header_version = 0
+log_header_ver = 2
dropped_event_id = 0xfffffffffffffffe
trace_fmt = '=QQQQQQQQ'
+header_fmt = '=QQII'
+header_len = struct.calcsize(header_fmt)
trace_len = struct.calcsize(trace_fmt)
event_re = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
+def get_event_argtypes(fobj):
+ """Parse a trace-events file into {event_num: (name, type arg, ...)}."""
+
+ events = {dropped_event_id: ('name', 'args')}
+ event_num = 0
+ for line in fobj:
+ m = event_re.match(line.strip())
+ if m is None:
+ continue
+
+ disable, name, args = m.groups()
+ events[event_num] = tuple(args.split(','))
+ event_num += 1
+ return events
+
+
def parse_events(fobj):
"""Parse a trace-events file into {event_num: (name, arg1, ...)}."""
@@ -48,15 +69,16 @@ def read_record(fobj):
return None
return struct.unpack(trace_fmt, s)
+def read_header(fobj):
+ '''Read a trace record header'''
+ s = fobj.read(header_len)
+ if len(s) != header_len:
+ return None
+ return struct.unpack(header_fmt, s)
+
+
def read_trace_file(fobj):
"""Deserialize trace records from a file, yielding record tuples (event_num, timestamp, arg1, ..., arg6)."""
- header = read_record(fobj)
- if header is None or \
- header[0] != header_event_id or \
- header[1] != header_magic or \
- header[2] != header_version:
- raise ValueError('not a trace file or incompatible version')
-
while True:
rec = read_record(fobj)
if rec is None:
@@ -64,6 +86,59 @@ def read_trace_file(fobj):
yield rec
+def process_event(event_id, fobj):
+ params = etypes[event_id]
+ for elem in params:
+ if is_string(elem):
+ l = fobj.read(4)
+ (len,) = struct.unpack('=L', l)
+ s = fobj.read(len)
+ sfmt = `len`+'s'
+ (str,) = struct.unpack_from(sfmt, s)
+ type, sep, var = elem.rpartition('*')
+ print '%(arg)s=%(val)s' % { 'arg': var.lstrip(), 'val': str },
+ elif '*' in elem:
+ (value,) = struct.unpack('=Q', fobj.read(8))
+ type, sep, var = elem.rpartition('*')
+ print '%(arg)s=0x%(val)u' % { 'arg': var.lstrip(), 'val': value },
+ else:
+ (value,) = struct.unpack('=Q', fobj.read(8))
+ type, sep, var = elem.rpartition(' ')
+ print '%(arg)s=%(val)u' % { 'arg': var.lstrip(), 'val': value },
+ print
+ return
+
+etypes = get_event_argtypes(open(sys.argv[1], 'r'))
+def processv2(fobj):
+ '''Process simpletrace v2 log trace records'''
+ events = parse_events(open(sys.argv[1], 'r'))
+ #print events
+ max_events = len(events) - 1
+ last_timestamp = None
+ while True:
+ # read record header
+ rechdr = read_header(fobj)
+ if rechdr is None:
+ print "No more records"
+ break
+
+ if rechdr[0] >= max_events:
+ print "Invalid Event ID found, Trace Log may be corrupted !!!"
+ sys.exit(1)
+
+ if last_timestamp is None:
+ last_timestamp = rechdr[1]
+ delta_ns = rechdr[1] - last_timestamp
+ last_timestamp = rechdr[1]
+
+ print events[rechdr[0]][0], '%0.3f' % (delta_ns / 1000.0),
+ # read data
+ # process_event(rec[0], fobj)
+ # rechdr[2] is record length (including header)
+ #print etypes[rechdr[0]]
+ #data = fobj.read(rechdr[2] - header_len)
+ process_event(rechdr[0], fobj)
+
class Analyzer(object):
"""A trace file analyzer which processes trace records.
@@ -90,8 +165,6 @@ def process(events, log, analyzer):
"""Invoke an analyzer on each event in a log."""
if isinstance(events, str):
events = parse_events(open(events, 'r'))
- if isinstance(log, str):
- log = open(log, 'rb')
def build_fn(analyzer, event):
fn = getattr(analyzer, event[0], None)
@@ -129,8 +202,10 @@ def run(analyzer):
sys.exit(1)
events = parse_events(open(sys.argv[1], 'r'))
- process(events, sys.argv[2], analyzer)
+ process(events, log, analyzer)
+
+log = open(sys.argv[2], 'rb')
if __name__ == '__main__':
class Formatter(Analyzer):
def __init__(self):
@@ -148,4 +223,16 @@ if __name__ == '__main__':
fields.append('%s=0x%x' % (event[i], rec[i + 1]))
print ' '.join(fields)
- run(Formatter())
+ header = read_header(log)
+ if header is None or \
+ header[0] != header_event_id or \
+ header[1] != header_magic:
+ raise ValueError('not a valid trace file')
+ if header[2] == 0: # version 1
+ # ver 1 tracelog header contains few more unused bytes
+ temp = log.read(40) # read those bytes and continue
+ run(Formatter())
+ elif header[2] == 2: # version 2
+ processv2(log)
+ else:
+ raise ValueError('trace file version not supported')
--
1.7.1.1
^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
@ 2012-01-10 14:50 ` Stefan Hajnoczi
2012-01-11 6:25 ` Harsh Bora
2012-01-10 21:45 ` Lluís Vilanova
` (2 subsequent siblings)
3 siblings, 1 reply; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-10 14:50 UTC (permalink / raw)
To: Harsh Prateek Bora
Cc: vilanova, mathieu.desnoyers, qemu-devel, stefanha, aneesh.kumar
On Tue, Jan 10, 2012 at 10:59 AM, Harsh Prateek Bora
<harsh@linux.vnet.ibm.com> wrote:
> diff --git a/scripts/tracetool.py b/scripts/tracetool.py
> new file mode 100755
> index 0000000..6874f66
> --- /dev/null
> +++ b/scripts/tracetool.py
> @@ -0,0 +1,585 @@
> +#!/usr/bin/env python
> +# Python based tracetool script (Code generator for trace events)
Nitpick: please don't use comments or names that reflect the fact that
you're changing something. Once this is merged readers might not even
know there was a non-Python tracetool script. "Code generator for
trace events" explains what this script does. "Python based tracetool
script" doesn't add any information because the content is clearly in
Python and the filename is tracetool.
A related point is please don't put simpletrace "v2" into the code
because if we ever do a v3 all those references would need to be
renamed, even if the value stays the same. (For example
ST_V2_REC_HDR_LEN.) When changing code make it look like it was
written like this from day 1 rather than leaving visible marks where
things were modified - git log already provides the code change
history. It's distracting and sometimes misleading when code contains
references to outdated things which have been replaced.
> +#
> +# Copyright IBM, Corp. 2011
> +#
> +# This work is licensed under the terms of the GNU GPL, version 2. See
> +# the COPYING file in the top-level directory.
> +#
> +#
> +
> +import sys
> +import getopt
> +
> +def usage():
> + print "Tracetool: Generate tracing code for trace events file on stdin"
> + print "Usage:"
> + print sys.argv[0], " --backend=[nop|simple|stderr|dtrace|ust] [-h|-c|-d|--stap]"
print 'a', 'b' puts a space between "a" and "b". "--backend=..."
would work fine, space is not needed.
> +def calc_sizeofargs(line):
> + args = get_args(line)
> + argc = get_argc(line)
> + strtype = ('const char*', 'char*', 'const char *', 'char *')
This is repeated elsewhere, please share is_string().
> +def trace_h_begin():
> + print '''#ifndef TRACE_H
> +#define TRACE_H
> +
> +/* This file is autogenerated by tracetool, do not edit. */
> +
> +#include "qemu-common.h"'''
> + return
A function that has no explicit return statement implicitly returns
None. Please remove returns to keep the code concise.
> +
> +def trace_h_end():
> + print '#endif /* TRACE_H */'
> + return
> +
> +def trace_c_begin():
> + print '/* This file is autogenerated by tracetool, do not edit. */'
> + return
> +
> +def trace_c_end():
> + # nop, required for trace_gen
> + return
def trace_c_end():
pass # nop, required for trace_gen
> +def simple_c(events):
> + rec_off = 0
> + print '#include "trace.h"'
> + print '#include "trace/simple.h"'
> + print
> + print 'TraceEvent trace_list[] = {'
> + print
> + eventlist = list(events)
> + for event in eventlist:
> + print '{.tp_name = "%(name)s", .state=0},' % {
> + 'name': event.name
> +}
> + print
> + print '};'
> + print
> + for event in eventlist:
> + argc = event.argc
> + print '''void trace_%(name)s(%(args)s)
> +{
> + unsigned int tbuf_idx, rec_off;
CC trace.o
trace.c: In function ‘trace_slavio_misc_update_irq_raise’:
trace.c:3411:28: warning: variable ‘rec_off’ set but not used
[-Wunused-but-set-variable]
> + uint64_t var64 __attribute__ ((unused));
> + uint64_t pvar64 __attribute__ ((unused));
> + uint32_t slen __attribute__ ((unused));
> +
> + if (!trace_list[%(event_id)s].state) {
> + return;
> + }
> +''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'event_id': event.num,
> +}
> + print '''
> + tbuf_idx = trace_alloc_record(%(event_id)s, %(sizestr)s);
> + rec_off = (tbuf_idx + ST_V2_REC_HDR_LEN) %% TRACE_BUF_LEN; /* seek record header */
This can be cleaned up with the following interface:
/**
* Initialize a trace record and claim space for it in the buffer
*
* @arglen number of bytes required for arguments
*/
void trace_record_start(TraceBufferRecord *rec, TraceEventID id, size_t arglen);
/**
* Append a 64-bit argument to a trace record
*/
void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val);
/**
* Append a string argument to a trace record
*/
void trace_record_write_str(TraceBufferRecord *rec, const char *s);
/**
* Mark a trace record completed
*
* Don't append any more arguments to the trace record after calling this.
*/
void trace_record_finish(TraceBufferRecord *rec);
Then tracetool.py and trace.c don't need to manage offsets or worry
about temporary variables. We also don't need to expose
ST_V2_REC_HDR_LEN here or wrap by TRACE_BUF_LEN.
The TraceBufferRecord encapsulates rec_off so that we don't need to
emit code that increments it. Instead trace_record_write_*() handles
that.
> +def stderr_h(events):
> + print '''#include <stdio.h>
> +#include "trace/stderr.h"
> +
> +extern TraceEvent trace_list[];'''
> + for event in events:
> + argnames = event.argnames
> + if event.argc > 0:
> + argnames = ', ' + event.argnames
> + else:
> + argnames = ''
> + print '''
> +static inline void trace_%(name)s(%(args)s)
> +{
> + if (trace_list[%(event_num)s].state != 0) {
> + fprintf(stderr, "%(name)s " %(fmt)s "\\n" %(argnames)s);
> + }
> +}''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'event_num': event.num,
> + 'fmt': event.fmt.rstrip('\n'),
We shouldn't be parsing the input here, please move the .rstrip() to
where the trace-events input gets parsed.
> +def trace_stap_begin():
> + global probeprefix
> + if backend != "dtrace":
> + print 'SystemTAP tapset generator not applicable to %s backend' % backend
> + sys.exit(1)
> + if binary == "":
> + print '--binary is required for SystemTAP tapset generator'
> + sys.exit(1)
> + if ((probeprefix == "") and (targettype == "")):
The parentheses are unnecessary. Here are two other ways of writing this:
if not probeprefix and not targettype:
or
if probeprefix == '' and targettype == '':
> +# Registry of backends and their converter functions
> +converters = {
> + 'simple': {
> + 'h': simple_h,
> + 'c': simple_c,
Missing space.
> +# Generator that yields Event objects given a trace-events file object
> +def read_events(fobj):
> + event_num = 0
> + for line in fobj:
> + if not line.strip():
> + continue
> + if line.lstrip().startswith('#'):
> + continue
> + yield Event(event_num, line)
> + event_num += 1
Indentation.
> +
> +backend = ""
> +output = ""
> +binary = ""
> +targettype = ""
> +targetarch = ""
> +probeprefix = ""
> +
> +def main():
> + global backend, output, binary, targettype, targetarch, probeprefix
Please avoid the globals, it tempts people to hack in bad things in
the future. The only globals that are hard to avoid are binary and
probeprefix.
If you move all the checks to main() before we start emitting output,
then there's no need to use most of these globals. In a way it makes
sense to do checks that abort before entering the main program.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record Harsh Prateek Bora
@ 2012-01-10 16:41 ` Stefan Hajnoczi
2012-01-18 9:14 ` Harsh Bora
0 siblings, 1 reply; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-10 16:41 UTC (permalink / raw)
To: Harsh Prateek Bora
Cc: vilanova, mathieu.desnoyers, qemu-devel, stefanha, aneesh.kumar
On Tue, Jan 10, 2012 at 10:59 AM, Harsh Prateek Bora
<harsh@linux.vnet.ibm.com> wrote:
> Advantages over existing simpletrace backend:
> - More than 6 elements (vitually unlimited) arguments can be traced.
> - This allows to trace strings (variable size element) as well.
>
> Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
> ---
> monitor.c | 2 +-
> trace/simple.c | 178 ++++++++++++++++++++------------------------------------
> trace/simple.h | 31 ++++++++--
> 3 files changed, 88 insertions(+), 123 deletions(-)
>
> diff --git a/monitor.c b/monitor.c
> index ffda0fe..b6f85d1 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -945,7 +945,7 @@ static void do_info_cpu_stats(Monitor *mon)
> #if defined(CONFIG_TRACE_SIMPLE)
> static void do_info_trace(Monitor *mon)
> {
> - st_print_trace((FILE *)mon, &monitor_fprintf);
> + /* FIXME: st_print_trace((FILE *)mon, &monitor_fprintf); */
This command is only available from the human monitor. It's not very
useful because it historically hasn't been able to pretty-print events
or show them in the right order (we use a ringbuffer but it prints
them out from index 0).
Therefore, I don't think we're under any obligation to keep this
command around. No one has complained about it's limitations - I
think this is a sign that no one has used it. I'd be okay with a
patch that removes it.
> }
> #endif
>
> diff --git a/trace/simple.c b/trace/simple.c
> index b639dda..65cafe2 100644
> --- a/trace/simple.c
> +++ b/trace/simple.c
> @@ -27,7 +27,7 @@
> #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL
>
> /** Trace file version number, bump if format changes */
> -#define HEADER_VERSION 0
> +#define HEADER_VERSION 2
>
> /** Records were dropped event ID */
> #define DROPPED_EVENT_ID (~(uint64_t)0 - 1)
> @@ -35,23 +35,6 @@
> /** Trace record is valid */
> #define TRACE_RECORD_VALID ((uint64_t)1 << 63)
>
> -/** Trace buffer entry */
> -typedef struct {
> - uint64_t event;
> - uint64_t timestamp_ns;
> - uint64_t x1;
> - uint64_t x2;
> - uint64_t x3;
> - uint64_t x4;
> - uint64_t x5;
> - uint64_t x6;
> -} TraceRecord;
> -
> -enum {
> - TRACE_BUF_LEN = 4096,
> - TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
> -};
> -
> /*
> * Trace records are written out by a dedicated thread. The thread waits for
> * records to become available, writes them out, and then waits again.
> @@ -62,11 +45,12 @@ static GCond *trace_empty_cond;
> static bool trace_available;
> static bool trace_writeout_enabled;
>
> -static TraceRecord trace_buf[TRACE_BUF_LEN];
> +uint8_t trace_buf[TRACE_BUF_LEN];
> static unsigned int trace_idx;
> static FILE *trace_fp;
> static char *trace_file_name = NULL;
>
> +
Spurious newline.
> /**
> * Read a trace record from the trace buffer
> *
> @@ -75,16 +59,19 @@ static char *trace_file_name = NULL;
> *
> * Returns false if the record is not valid.
> */
> -static bool get_trace_record(unsigned int idx, TraceRecord *record)
> +static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
> {
> - if (!(trace_buf[idx].event & TRACE_RECORD_VALID)) {
> + TraceRecord *record = (TraceRecord *) &trace_buf[idx];
> + if (!(record->event & TRACE_RECORD_VALID)) {
> return false;
> }
>
> __sync_synchronize(); /* read memory barrier before accessing record */
>
> - *record = trace_buf[idx];
> - record->event &= ~TRACE_RECORD_VALID;
> + *recordptr = g_malloc(record->length);
> + /* make a copy of record to avoid being overwritten */
> + memcpy(*recordptr, record, record->length);
> + (*recordptr)->event &= ~TRACE_RECORD_VALID;
> return true;
> }
>
> @@ -106,6 +93,47 @@ static void flush_trace_file(bool wait)
> g_static_mutex_unlock(&trace_lock);
> }
>
> +unsigned int trace_alloc_record(TraceEventID event, uint32_t datasize)
> +{
> + unsigned int idx, rec_off;
> + uint32_t rec_len = ST_V2_REC_HDR_LEN + datasize;
> + uint64_t timestamp_ns = get_clock();
> +
> + idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) % TRACE_BUF_LEN;
> + rec_off = idx;
> + write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
> + rec_off += sizeof(event);
> + write_to_buffer(rec_off, (uint8_t*)×tamp_ns, sizeof(timestamp_ns));
> + rec_off += sizeof(timestamp_ns);
> + write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len));
> + rec_off += sizeof(rec_len);
> + return idx;
> +}
> +
> +void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size)
> +{
> + uint32_t x = 0;
> + while (x < size)
> + {
> + if (idx >= TRACE_BUF_LEN) {
> + idx = idx % TRACE_BUF_LEN;
> + }
> + trace_buf[idx++] = dataptr[x++];
> + }
> +}
> +
> +void trace_mark_record_complete(unsigned int idx)
> +{
> + TraceRecord *record = (TraceRecord*) &trace_buf[idx];
> +
> + __sync_synchronize(); /* write barrier before marking as valid */
> + record->event |= TRACE_RECORD_VALID;
> +
> + if (idx > TRACE_BUF_FLUSH_THRESHOLD) {
> + flush_trace_file(false);
> + }
This looks suspicious. We want to kick the writeout thread when the
buffer reaches the threshold but not repeatedly after that. Also
because it's a ring buffer idx could "start" above the threshold.
Perhaps something like:
if (idx > TRACE_BUF_FLUSH_THRESHOLD && old_idx <= TRACE_BUF_FLUSH_THRESHOLD) {
flush_trace_file(false);
}
> +}
> +
> static void wait_for_trace_records_available(void)
> {
> g_static_mutex_lock(&trace_lock);
> @@ -120,7 +148,7 @@ static void wait_for_trace_records_available(void)
>
> static gpointer writeout_thread(gpointer opaque)
> {
> - TraceRecord record;
> + TraceRecord record, *recordptr;
> unsigned int writeout_idx = 0;
> unsigned int num_available, idx;
> size_t unused __attribute__ ((unused));
> @@ -130,19 +158,20 @@ static gpointer writeout_thread(gpointer opaque)
>
> num_available = trace_idx - writeout_idx;
> if (num_available > TRACE_BUF_LEN) {
> - record = (TraceRecord){
> - .event = DROPPED_EVENT_ID,
> - .x1 = num_available,
> - };
> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
> + record.event = DROPPED_EVENT_ID,
> + record.length = num_available,
Please don't use .length for the number of bytes dropped because this
makes life harder for parsing scripts like simpletrace.py. They would
need a special case to check for DROPPED_EVENT_ID and then treat
.length as an argument. Instead the number of bytes should be an
argument.
Also, by removing the struct literal assignment you lose the automatic
zeroing of fields. We'll write out junk data - it would be nicer to
clear it.
> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
> writeout_idx += num_available;
> }
>
> idx = writeout_idx % TRACE_BUF_LEN;
> - while (get_trace_record(idx, &record)) {
> - trace_buf[idx].event = 0; /* clear valid bit */
> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
> - idx = ++writeout_idx % TRACE_BUF_LEN;
> + while (get_trace_record(idx, &recordptr)) {
> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
> + writeout_idx += recordptr->length;
> + g_free(recordptr);
> + recordptr = (TraceRecord *) &trace_buf[idx];
> + recordptr->event = 0;
> + idx = writeout_idx % TRACE_BUF_LEN;
> }
I'm wondering if it's worth using a different approach here. Writing
out individual records has bothered me.
If we have a second buffer, as big as trace_buf[], then a function can
copy out all records and make them available in trace_buf again:
/**
* Copy completed trace records out of the ring buffer
*
* @idx offset into trace_buf[]
* @buf destination buffer
* @len size of destination buffer
* @ret the number of bytes consumed
*/
size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
That means consume gobbles up as many records as it can:
* Until it reaches an invalid record which has not been written yet
* Until it reaches the end of trace_buf[], the caller can call again
with idx wrapped to 0
After copying into buf[] it clears the valid bit in trace_buf[].
Then the loop which calls consume_trace_records() does a single
fwrite(3) and increments idx/writeout_idx.
The advantage to this is that we write many records in one go and I
think it splits up the writeout steps a little nicer than what we've
previously done.
>
> fflush(trace_fp);
> @@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
> static const TraceRecord header = {
> .event = HEADER_EVENT_ID,
> .timestamp_ns = HEADER_MAGIC,
> - .x1 = HEADER_VERSION,
> + .length = HEADER_VERSION,
Hmm...this is kind of ugly (see comment about using .length above) but
in this case most parsers will have a special-case anyway to check the
magic number. We need to use the .length field because historically
that's where the version is located.
> +/* Interfaces for simpletrace v2 */
Please drop this comment. All trace/simple.[ch] code is for v2, this
makes it seems like we support both versions at the same time.
> +
> +/** Trace buffer entry */
> +typedef struct {
> + uint64_t event; /* TraceEventID */
> + uint64_t timestamp_ns;
> + uint32_t length; /* in bytes */
> + uint32_t reserved; /* unused */
> + uint8_t arguments[]; /* arguments position affects ST_V2_REC_HDR_LEN */
> +} TraceRecord;
Does this need to be visible? I think it can live in trace/simple.c
> +
> +#define ST_V2_REC_HDR_LEN 24
Does not need to be visible. Also why calculate manually, instead of
a macro I would use sizeof(TraceRecord) (the array without elements is
not counted by sizeof).
> +
> +enum {
> + TRACE_BUF_LEN = 4096 * 64,
> + TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
> +};
Does not need to be visible.
> +
> +extern uint8_t trace_buf[TRACE_BUF_LEN];
Does not need to be visible.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
2012-01-10 14:50 ` Stefan Hajnoczi
@ 2012-01-10 21:45 ` Lluís Vilanova
2012-01-11 17:14 ` Stefan Hajnoczi
2012-01-10 22:51 ` Lluís Vilanova
2012-01-11 10:07 ` Stefan Hajnoczi
3 siblings, 1 reply; 23+ messages in thread
From: Lluís Vilanova @ 2012-01-10 21:45 UTC (permalink / raw)
To: Harsh Prateek Bora; +Cc: aneesh.kumar, mathieu.desnoyers, qemu-devel, stefanha
Harsh Prateek Bora writes:
> Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
> ---
> Makefile.objs | 6 +-
> Makefile.target | 10 +-
> configure | 7 +-
> scripts/tracetool | 643 --------------------------------------------------
> scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
> 5 files changed, 597 insertions(+), 654 deletions(-)
> delete mode 100755 scripts/tracetool
> create mode 100755 scripts/tracetool.py
Cannot be applied on top of Stefan's tracing branch (AFAIK, it has only one
commit pending merge into upstream).
Stefan, are you waiting for more patches to accumulate before merging your
branch, or is it just waiting for a prediodical merge?
Thanks,
Lluis
--
"And it's much the same thing with knowledge, for whenever you learn
something new, the whole world becomes that much richer."
-- The Princess of Pure Reason, as told by Norton Juster in The Phantom
Tollbooth
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
2012-01-10 14:50 ` Stefan Hajnoczi
2012-01-10 21:45 ` Lluís Vilanova
@ 2012-01-10 22:51 ` Lluís Vilanova
2012-01-11 6:38 ` Harsh Bora
2012-01-12 9:33 ` Stefan Hajnoczi
2012-01-11 10:07 ` Stefan Hajnoczi
3 siblings, 2 replies; 23+ messages in thread
From: Lluís Vilanova @ 2012-01-10 22:51 UTC (permalink / raw)
To: Harsh Prateek Bora; +Cc: aneesh.kumar, qemu-devel, stefanha
Harsh Prateek Bora writes:
> Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
> ---
> Makefile.objs | 6 +-
> Makefile.target | 10 +-
> configure | 7 +-
> scripts/tracetool | 643 --------------------------------------------------
> scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
> 5 files changed, 597 insertions(+), 654 deletions(-)
> delete mode 100755 scripts/tracetool
> create mode 100755 scripts/tracetool.py
[...]
> diff --git a/scripts/tracetool.py b/scripts/tracetool.py
> new file mode 100755
> index 0000000..6874f66
> --- /dev/null
> +++ b/scripts/tracetool.py
> @@ -0,0 +1,585 @@
> +#!/usr/bin/env python
> +# Python based tracetool script (Code generator for trace events)
> +#
> +# Copyright IBM, Corp. 2011
> +#
> +# This work is licensed under the terms of the GNU GPL, version 2. See
> +# the COPYING file in the top-level directory.
> +#
> +#
> +
> +import sys
> +import getopt
> +
> +def usage():
> + print "Tracetool: Generate tracing code for trace events file on stdin"
> + print "Usage:"
> + print sys.argv[0], " --backend=[nop|simple|stderr|dtrace|ust] [-h|-c|-d|--stap]"
> + print '''
> +Backends:
> + --nop Tracing disabled
> + --simple Simple built-in backend
> + --stderr Stderr built-in backend
> + --dtrace DTrace/SystemTAP backend
> + --ust LTTng User Space Tracing backend
> +
> +Output formats:
> + -h Generate .h file
> + -c Generate .c file
> + -d Generate .d file (DTrace only)
> + --stap Generate .stp file (DTrace with SystemTAP only)
> +
> +Options:
> + --binary [path] Full path to QEMU binary
> + --target-arch [arch] QEMU emulator target arch
> + --target-type [type] QEMU emulator target type ('system' or 'user')
> + --probe-prefix [prefix] Prefix for dtrace probe names
> + (default: qemu-targettype-targetarch)
> +'''
> + sys.exit(1)
> +
> +def get_name(line, sep='('):
> + head, sep, tail = line.partition(sep)
> + return head
> +
> +def get_args(line, sep1='(', sep2=')'):
> + head, sep1, tail = line.partition(sep1)
> + args, sep2, fmt_str = tail.partition(sep2)
> + return args
> +
> +def get_argnames(line, sep=','):
> + nfields = 0
> + str = []
> + args = get_args(line)
> + for field in args.split():
> + nfields = nfields + 1
> + # Drop pointer star
> + type, ptr, tail = field.partition('*')
> + if type != field:
> + field = tail
> +
> + name, sep, tail = field.partition(',')
> +
> + if name == field:
> + continue
> + str.append(name)
> + str.append(", ")
> +
> + if nfields > 1:
> + str.append(name)
> + return ''.join(str)
> + else:
> + return ''
> +
> +def get_argc(line):
> + argc = 0
> + argnames = get_argnames(line)
> + if argnames:
> + for name in argnames.split(','):
> + argc = argc + 1
> + return argc
> +
> +def get_fmt(line, sep=')'):
> + event, sep, fmt = line.partition(sep)
> + return fmt
> +
> +def calc_sizeofargs(line):
> + args = get_args(line)
> + argc = get_argc(line)
> + strtype = ('const char*', 'char*', 'const char *', 'char *')
> + str = []
> + newstr = ""
> + if argc > 0:
> + str = args.split(',')
> + for elem in str:
> + if elem.lstrip().startswith(strtype): #strings
> + type, sep, var = elem.rpartition('*')
> + newstr = newstr+"4 + strlen("+var.lstrip()+") + "
> + #elif '*' in elem:
> + # newstr = newstr + "4 + " # pointer vars
> + else:
> + #type, sep, var = elem.rpartition(' ')
> + #newstr = newstr+"sizeof("+type.lstrip()+") + "
> + newstr = newstr + '8 + '
> + newstr = newstr + '0' # for last +
> + return newstr
> +
> +
> +def trace_h_begin():
> + print '''#ifndef TRACE_H
> +#define TRACE_H
> +
> +/* This file is autogenerated by tracetool, do not edit. */
> +
> +#include "qemu-common.h"'''
> + return
> +
> +def trace_h_end():
> + print '#endif /* TRACE_H */'
> + return
> +
> +def trace_c_begin():
> + print '/* This file is autogenerated by tracetool, do not edit. */'
> + return
> +
> +def trace_c_end():
> + # nop, required for trace_gen
> + return
> +
> +def nop_h(events):
> + print
> + for event in events:
> + print '''static inline void trace_%(name)s(%(args)s)
> +{
> +}
> +''' % {
> + 'name': event.name,
> + 'args': event.args
> +}
> + return
> +
> +def nop_c(events):
> + # nop, reqd for converters
> + return
> +
> +
> +def simple_h(events):
> + print '#include "trace/simple.h"'
> + print
> + for event in events:
> + print 'void trace_%(name)s(%(args)s);' % {
> + 'name': event.name,
> + 'args': event.args
> +}
> + print
> + print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
> + print 'extern TraceEvent trace_list[NR_TRACE_EVENTS];'
> +
> + return
> +
> +def is_string(arg):
> + strtype = ('const char*', 'char*', 'const char *', 'char *')
> + if arg.lstrip().startswith(strtype):
> + return True
> + else:
> + return False
> +
> +def simple_c(events):
> + rec_off = 0
> + print '#include "trace.h"'
> + print '#include "trace/simple.h"'
> + print
> + print 'TraceEvent trace_list[] = {'
> + print
> + eventlist = list(events)
> + for event in eventlist:
> + print '{.tp_name = "%(name)s", .state=0},' % {
> + 'name': event.name
> +}
> + print
> + print '};'
> + print
> + for event in eventlist:
> + argc = event.argc
> + print '''void trace_%(name)s(%(args)s)
> +{
> + unsigned int tbuf_idx, rec_off;
> + uint64_t var64 __attribute__ ((unused));
> + uint64_t pvar64 __attribute__ ((unused));
> + uint32_t slen __attribute__ ((unused));
> +
> + if (!trace_list[%(event_id)s].state) {
> + return;
> + }
> +''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'event_id': event.num,
> +}
> + print '''
> + tbuf_idx = trace_alloc_record(%(event_id)s, %(sizestr)s);
> + rec_off = (tbuf_idx + ST_V2_REC_HDR_LEN) %% TRACE_BUF_LEN; /* seek record header */
> +''' % {'event_id': event.num, 'sizestr': event.sizestr,}
> +
> + if argc > 0:
> + str = event.arglist
> + for elem in str:
> + if is_string(elem): # if string
> + type, sep, var = elem.rpartition('*')
> + print '''
> + slen = strlen(%(var)s);
> + write_to_buffer(rec_off, (uint8_t*)&slen, sizeof(slen));
> + rec_off += sizeof(slen);''' % {
> + 'var': var.lstrip()
> +}
> + print '''
> + write_to_buffer(rec_off, (uint8_t*)%(var)s, slen);
> + rec_off += slen;''' % {
> + 'var': var.lstrip()
> +}
> + elif '*' in elem: # pointer var (not string)
> + type, sep, var = elem.rpartition('*')
> + print '''
> + pvar64 = (uint64_t)(uint64_t*)%(var)s;
> + write_to_buffer(rec_off, (uint8_t*)&pvar64, sizeof(uint64_t));
> + rec_off += sizeof(uint64_t);''' % {
> + 'var': var.lstrip()
> +}
> + else: # primitive data type
> + type, sep, var = elem.rpartition(' ')
> + print '''
> + var64 = (uint64_t)%(var)s;
> + write_to_buffer(rec_off, (uint8_t*)&var64, sizeof(uint64_t));
> + rec_off += sizeof(uint64_t);''' % {
> + 'var': var.lstrip()
> +}
> + print '''
> + trace_mark_record_complete(tbuf_idx);'''
> + print '}'
> + print
> +
> + return
> +
> +def stderr_h(events):
> + print '''#include <stdio.h>
> +#include "trace/stderr.h"
> +
> +extern TraceEvent trace_list[];'''
> + for event in events:
> + argnames = event.argnames
> + if event.argc > 0:
> + argnames = ', ' + event.argnames
> + else:
> + argnames = ''
> + print '''
> +static inline void trace_%(name)s(%(args)s)
> +{
> + if (trace_list[%(event_num)s].state != 0) {
> + fprintf(stderr, "%(name)s " %(fmt)s "\\n" %(argnames)s);
> + }
> +}''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'event_num': event.num,
> + 'fmt': event.fmt.rstrip('\n'),
> + 'argnames': argnames
> +}
> + print
> + print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
> +
> +def stderr_c(events):
> + print '''#include "trace.h"
> +
> +TraceEvent trace_list[] = {
> +'''
> + for event in events:
> + print '{.tp_name = "%(name)s", .state=0},' % {
> + 'name': event.name
> +}
> + print
> + print '};'
> +
> +def ust_h(events):
> + print '''#include <ust/tracepoint.h>
> +#undef mutex_lock
> +#undef mutex_unlock
> +#undef inline
> +#undef wmb'''
> +
> + for event in events:
> + if event.argc > 0:
> + print '''
> +DECLARE_TRACE(ust_%(name)s, TP_PROTO(%(args)s), TP_ARGS(%(argnames)s));
> +#define trace_%(name)s trace_ust_%(name)s''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'argnames': event.argnames
> +}
> + else:
> + print '''
> +_DECLARE_TRACEPOINT_NOARGS(ust_%(name)s);
> +#define trace_%(name)s trace_ust_%(name)s''' % {
> + 'name': event.name,
> +}
> + print
> + return
> +
> +def ust_c(events):
> + print '''#include <ust/marker.h>
> +#undef mutex_lock
> +#undef mutex_unlock
> +#undef inline
> +#undef wmb
> +#include "trace.h"'''
> + eventlist = list(events)
> + for event in eventlist:
> + argnames = event.argnames
> + if event.argc > 0:
> + argnames = ', ' + event.argnames
> + print '''
> +DEFINE_TRACE(ust_%(name)s);
> +
> +static void ust_%(name)s_probe(%(args)s)
> +{
> + trace_mark(ust, %(name)s, %(fmt)s%(argnames)s);
> +}''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'fmt': event.fmt.rstrip('\n'),
> + 'argnames': argnames
> +}
> + else:
> + print '''
> +DEFINE_TRACE(ust_%(name)s);
> +
> +static void ust_%(name)s_probe(%(args)s)
> +{
> + trace_mark(ust, %(name)s, UST_MARKER_NOARGS);
> +}''' % {
> + 'name': event.name,
> + 'args': event.args,
> +}
> +
> + # register probes
> + print '''
> +static void __attribute__((constructor)) trace_init(void)
> +{'''
> + for event in eventlist:
> + print ' register_trace_ust_%(name)s(ust_%(name)s_probe);' % {
> + 'name': event.name
> +}
> + print '}'
> +
> + return
> +
> +def dtrace_h(events):
> + print '#include "trace-dtrace.h"'
> + print
> + for event in events:
> + print '''static inline void trace_%(name)s(%(args)s) {
> + if (QEMU_%(uppername)s_ENABLED()) {
> + QEMU_%(uppername)s(%(argnames)s);
> + }
> +}
> +''' % {
> + 'name': event.name,
> + 'args': event.args,
> + 'uppername': event.name.upper(),
> + 'argnames': event.argnames,
> +}
> +
> +def dtrace_c(events):
> + return # No need for function definitions in dtrace backend
> +
> +def dtrace_d(events):
> + print 'provider qemu {'
> + for event in events:
> + args = event.args
> +
> + # DTrace provider syntax expects foo() for empty
> + # params, not foo(void)
> + if args == 'void':
> + args = ''
> +
> + # Define prototype for probe arguments
> + print '''
> + probe %(name)s(%(args)s);''' % {
> + 'name': event.name,
> + 'args': args
> +}
> + print
> + print '};'
> + return
> +
> +def dtrace_stp(events):
> + for event in events:
> + # Define prototype for probe arguments
> + print '''
> +probe %(probeprefix)s.%(name)s = process("%(binary)s").mark("%(name)s")
> +{''' % {
> + 'probeprefix': probeprefix,
> + 'name': event.name,
> + 'binary': binary
> +}
> + i = 1
> + if event.argc > 0:
> + for arg in event.argnames.split(','):
> + # 'limit' is a reserved keyword
> + if arg == 'limit':
> + arg = '_limit'
> + print ' %s = $arg%d;' % (arg.lstrip(), i)
> + i += 1
> + print '}'
> + print
> + return
> +
> +def trace_stap_begin():
> + global probeprefix
> + if backend != "dtrace":
> + print 'SystemTAP tapset generator not applicable to %s backend' % backend
> + sys.exit(1)
> + if binary == "":
> + print '--binary is required for SystemTAP tapset generator'
> + sys.exit(1)
> + if ((probeprefix == "") and (targettype == "")):
> + print '--target-type is required for SystemTAP tapset generator'
> + sys.exit(1)
> + if ((probeprefix == "") and (targetarch == "")):
> + print '--target-arch is required for SystemTAP tapset generator'
> + sys.exit(1)
> + if probeprefix == "":
> + probeprefix = 'qemu.' + targettype + '.' + targetarch
> + print '/* This file is autogenerated by tracetool, do not edit. */'
> + return
> +
> +def trace_stap_end():
> + return #nop, reqd for trace_gen
> +
> +def trace_d_begin():
> + if backend != 'dtrace':
> + print 'DTrace probe generator not applicable to %s backend' % backend
> + sys.exit(1)
> + print '/* This file is autogenerated by tracetool, do not edit. */'
> +
> +def trace_d_end():
> + return #nop, reqd for trace_gen
> +
> +
> +# Registry of backends and their converter functions
> +converters = {
> + 'simple': {
> + 'h': simple_h,
> + 'c': simple_c,
> + },
> +
> + 'nop': {
> + 'h': nop_h,
> + 'c': nop_c,
> + },
> +
> + 'stderr': {
> + 'h': stderr_h,
> + 'c': stderr_c,
> + },
> +
> + 'dtrace': {
> + 'h': dtrace_h,
> + 'c': dtrace_c,
> + 'd': dtrace_d,
> + 'stap': dtrace_stp
> + },
> +
> + 'ust': {
> + 'h': ust_h,
> + 'c': ust_c,
> + },
> +
> +}
> +
> +# Trace file header and footer code generators
> +trace_gen = {
> + 'h': {
> + 'begin': trace_h_begin,
> + 'end': trace_h_end,
> + },
> + 'c': {
> + 'begin': trace_c_begin,
> + 'end': trace_c_end,
> + },
> + 'd': {
> + 'begin': trace_d_begin,
> + 'end': trace_d_end,
> + },
> + 'stap': {
> + 'begin': trace_stap_begin,
> + 'end': trace_stap_end,
> + },
> +}
> +
> +# A trace event
> +class Event(object):
> + def __init__(self, num, line):
> + self.num = num
> + self.args = get_args(line)
> + self.arglist = self.args.split(',')
> + self.name = get_name(line)
> + self.argc = get_argc(line)
> + self.argnames = get_argnames(line)
> + self.sizestr = calc_sizeofargs(line)
> + self.fmt = get_fmt(line)
This is not not extracting the event properties (e.g., disable). A set of
strings should suffice.
Arguments could be converted to an Arguments class (or similar, like
ArgumentList) and derive the rest from there using methods (e.g., names, types,
sizestr, arglist, etc.).
If you want, I can send a patch on top of this one with that.
> +
> +# Generator that yields Event objects given a trace-events file object
> +def read_events(fobj):
> + event_num = 0
> + for line in fobj:
> + if not line.strip():
> + continue
> + if line.lstrip().startswith('#'):
> + continue
> + yield Event(event_num, line)
> + event_num += 1
> +
> +backend = ""
> +output = ""
> +binary = ""
> +targettype = ""
> +targetarch = ""
> +probeprefix = ""
> +
> +def main():
> + global backend, output, binary, targettype, targetarch, probeprefix
> + supported_backends = ["simple", "nop", "stderr", "dtrace", "ust"]
> + short_options = "hcd"
> + long_options = ["stap", "backend=", "binary=", "target-arch=", "target-type=", "probe-prefix=", "list-backends", "check-backend"]
> + try:
> + opts, args = getopt.getopt(sys.argv[1:], short_options, long_options)
> + except getopt.GetoptError, err:
> + # print help information and exit:
> + print str(err) # will print something like "option -a not recognized"
> + usage()
> + sys.exit(2)
> + for opt, arg in opts:
> + if opt == '-h':
> + output = 'h'
> + elif opt == '-c':
> + output = 'c'
> + elif opt == '-d':
> + output = 'd'
> + elif opt == '--stap':
> + output = 'stap'
> + elif opt == '--backend':
> + backend = arg
> + elif opt == '--binary':
> + binary = arg
> + elif opt == '--target-arch':
> + targetarch = arg
> + elif opt == '--target-type':
> + targettype = arg
> + elif opt == '--probe-prefix':
> + probeprefix = arg
> + elif opt == '--list-backends':
> + print 'simple, nop, stderr, dtrace'
> + sys.exit(0)
> + elif opt == "--check-backend":
> + if any(backend in s for s in supported_backends):
> + sys.exit(0)
> + else:
> + sys.exit(1)
> + else:
> + #assert False, "unhandled option"
> + print "unhandled option: ", opt
> + usage()
> +
> + if backend == "" or output == "":
> + usage()
> + sys.exit(0)
> +
> + events = read_events(sys.stdin)
> + trace_gen[output]['begin']()
> + converters[backend][output](events)
This should use the "disable" property to establish whether to use output or
"nop".
> + trace_gen[output]['end']()
> + return
> +
> +if __name__ == "__main__":
> + main()
> +
> --
> 1.7.1.1
Lluis
--
"And it's much the same thing with knowledge, for whenever you learn
something new, the whole world becomes that much richer."
-- The Princess of Pure Reason, as told by Norton Juster in The Phantom
Tollbooth
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 14:50 ` Stefan Hajnoczi
@ 2012-01-11 6:25 ` Harsh Bora
2012-01-11 10:03 ` Stefan Hajnoczi
0 siblings, 1 reply; 23+ messages in thread
From: Harsh Bora @ 2012-01-11 6:25 UTC (permalink / raw)
To: Stefan Hajnoczi, stefanha
Cc: vilanova, mathieu.desnoyers, qemu-devel, aneesh.kumar
Hi Stefan,
Thanks for an early review, I shall address your comments in next version.
Also, please confirm, whether I should work on top for qemu.git or your
tracing branch on repo.or.cz/stefanha.git ?
regards,
Harsh
On 01/10/2012 08:20 PM, Stefan Hajnoczi wrote:
> On Tue, Jan 10, 2012 at 10:59 AM, Harsh Prateek Bora
> <harsh@linux.vnet.ibm.com> wrote:
>> diff --git a/scripts/tracetool.py b/scripts/tracetool.py
>> new file mode 100755
>> index 0000000..6874f66
>> --- /dev/null
>> +++ b/scripts/tracetool.py
>> @@ -0,0 +1,585 @@
>> +#!/usr/bin/env python
>> +# Python based tracetool script (Code generator for trace events)
>
> Nitpick: please don't use comments or names that reflect the fact that
> you're changing something. Once this is merged readers might not even
> know there was a non-Python tracetool script. "Code generator for
> trace events" explains what this script does. "Python based tracetool
> script" doesn't add any information because the content is clearly in
> Python and the filename is tracetool.
>
> A related point is please don't put simpletrace "v2" into the code
> because if we ever do a v3 all those references would need to be
> renamed, even if the value stays the same. (For example
> ST_V2_REC_HDR_LEN.) When changing code make it look like it was
> written like this from day 1 rather than leaving visible marks where
> things were modified - git log already provides the code change
> history. It's distracting and sometimes misleading when code contains
> references to outdated things which have been replaced.
>
>> +#
>> +# Copyright IBM, Corp. 2011
>> +#
>> +# This work is licensed under the terms of the GNU GPL, version 2. See
>> +# the COPYING file in the top-level directory.
>> +#
>> +#
>> +
>> +import sys
>> +import getopt
>> +
>> +def usage():
>> + print "Tracetool: Generate tracing code for trace events file on stdin"
>> + print "Usage:"
>> + print sys.argv[0], " --backend=[nop|simple|stderr|dtrace|ust] [-h|-c|-d|--stap]"
>
> print 'a', 'b' puts a space between "a" and "b". "--backend=..."
> would work fine, space is not needed.
>
>> +def calc_sizeofargs(line):
>> + args = get_args(line)
>> + argc = get_argc(line)
>> + strtype = ('const char*', 'char*', 'const char *', 'char *')
>
> This is repeated elsewhere, please share is_string().
>
>> +def trace_h_begin():
>> + print '''#ifndef TRACE_H
>> +#define TRACE_H
>> +
>> +/* This file is autogenerated by tracetool, do not edit. */
>> +
>> +#include "qemu-common.h"'''
>> + return
>
> A function that has no explicit return statement implicitly returns
> None. Please remove returns to keep the code concise.
>
>> +
>> +def trace_h_end():
>> + print '#endif /* TRACE_H */'
>> + return
>> +
>> +def trace_c_begin():
>> + print '/* This file is autogenerated by tracetool, do not edit. */'
>> + return
>> +
>> +def trace_c_end():
>> + # nop, required for trace_gen
>> + return
>
> def trace_c_end():
> pass # nop, required for trace_gen
>
>> +def simple_c(events):
>> + rec_off = 0
>> + print '#include "trace.h"'
>> + print '#include "trace/simple.h"'
>> + print
>> + print 'TraceEvent trace_list[] = {'
>> + print
>> + eventlist = list(events)
>> + for event in eventlist:
>> + print '{.tp_name = "%(name)s", .state=0},' % {
>> + 'name': event.name
>> +}
>> + print
>> + print '};'
>> + print
>> + for event in eventlist:
>> + argc = event.argc
>> + print '''void trace_%(name)s(%(args)s)
>> +{
>> + unsigned int tbuf_idx, rec_off;
>
> CC trace.o
> trace.c: In function ‘trace_slavio_misc_update_irq_raise’:
> trace.c:3411:28: warning: variable ‘rec_off’ set but not used
> [-Wunused-but-set-variable]
>
>> + uint64_t var64 __attribute__ ((unused));
>> + uint64_t pvar64 __attribute__ ((unused));
>> + uint32_t slen __attribute__ ((unused));
>> +
>> + if (!trace_list[%(event_id)s].state) {
>> + return;
>> + }
>> +''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'event_id': event.num,
>> +}
>> + print '''
>> + tbuf_idx = trace_alloc_record(%(event_id)s, %(sizestr)s);
>> + rec_off = (tbuf_idx + ST_V2_REC_HDR_LEN) %% TRACE_BUF_LEN; /* seek record header */
>
> This can be cleaned up with the following interface:
>
> /**
> * Initialize a trace record and claim space for it in the buffer
> *
> * @arglen number of bytes required for arguments
> */
> void trace_record_start(TraceBufferRecord *rec, TraceEventID id, size_t arglen);
>
> /**
> * Append a 64-bit argument to a trace record
> */
> void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val);
>
> /**
> * Append a string argument to a trace record
> */
> void trace_record_write_str(TraceBufferRecord *rec, const char *s);
>
> /**
> * Mark a trace record completed
> *
> * Don't append any more arguments to the trace record after calling this.
> */
> void trace_record_finish(TraceBufferRecord *rec);
>
> Then tracetool.py and trace.c don't need to manage offsets or worry
> about temporary variables. We also don't need to expose
> ST_V2_REC_HDR_LEN here or wrap by TRACE_BUF_LEN.
>
> The TraceBufferRecord encapsulates rec_off so that we don't need to
> emit code that increments it. Instead trace_record_write_*() handles
> that.
>
>> +def stderr_h(events):
>> + print '''#include<stdio.h>
>> +#include "trace/stderr.h"
>> +
>> +extern TraceEvent trace_list[];'''
>> + for event in events:
>> + argnames = event.argnames
>> + if event.argc> 0:
>> + argnames = ', ' + event.argnames
>> + else:
>> + argnames = ''
>> + print '''
>> +static inline void trace_%(name)s(%(args)s)
>> +{
>> + if (trace_list[%(event_num)s].state != 0) {
>> + fprintf(stderr, "%(name)s " %(fmt)s "\\n" %(argnames)s);
>> + }
>> +}''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'event_num': event.num,
>> + 'fmt': event.fmt.rstrip('\n'),
>
> We shouldn't be parsing the input here, please move the .rstrip() to
> where the trace-events input gets parsed.
>
>> +def trace_stap_begin():
>> + global probeprefix
>> + if backend != "dtrace":
>> + print 'SystemTAP tapset generator not applicable to %s backend' % backend
>> + sys.exit(1)
>> + if binary == "":
>> + print '--binary is required for SystemTAP tapset generator'
>> + sys.exit(1)
>> + if ((probeprefix == "") and (targettype == "")):
>
> The parentheses are unnecessary. Here are two other ways of writing this:
>
> if not probeprefix and not targettype:
>
> or
>
> if probeprefix == '' and targettype == '':
>
>> +# Registry of backends and their converter functions
>> +converters = {
>> + 'simple': {
>> + 'h': simple_h,
>> + 'c': simple_c,
>
> Missing space.
>
>> +# Generator that yields Event objects given a trace-events file object
>> +def read_events(fobj):
>> + event_num = 0
>> + for line in fobj:
>> + if not line.strip():
>> + continue
>> + if line.lstrip().startswith('#'):
>> + continue
>> + yield Event(event_num, line)
>> + event_num += 1
>
> Indentation.
>
>> +
>> +backend = ""
>> +output = ""
>> +binary = ""
>> +targettype = ""
>> +targetarch = ""
>> +probeprefix = ""
>> +
>> +def main():
>> + global backend, output, binary, targettype, targetarch, probeprefix
>
> Please avoid the globals, it tempts people to hack in bad things in
> the future. The only globals that are hard to avoid are binary and
> probeprefix.
>
> If you move all the checks to main() before we start emitting output,
> then there's no need to use most of these globals. In a way it makes
> sense to do checks that abort before entering the main program.
>
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 22:51 ` Lluís Vilanova
@ 2012-01-11 6:38 ` Harsh Bora
2012-01-11 8:46 ` Harsh Bora
2012-01-12 9:33 ` Stefan Hajnoczi
1 sibling, 1 reply; 23+ messages in thread
From: Harsh Bora @ 2012-01-11 6:38 UTC (permalink / raw)
To: Lluís Vilanova; +Cc: aneesh.kumar, qemu-devel, stefanha
On 01/11/2012 04:21 AM, Lluís Vilanova wrote:
> Harsh Prateek Bora writes:
>
>> Signed-off-by: Harsh Prateek Bora<harsh@linux.vnet.ibm.com>
>> ---
>> Makefile.objs | 6 +-
>> Makefile.target | 10 +-
>> configure | 7 +-
>> scripts/tracetool | 643 --------------------------------------------------
>> scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
>> 5 files changed, 597 insertions(+), 654 deletions(-)
>> delete mode 100755 scripts/tracetool
>> create mode 100755 scripts/tracetool.py
>
> [...]
>> diff --git a/scripts/tracetool.py b/scripts/tracetool.py
>> new file mode 100755
>> index 0000000..6874f66
>> --- /dev/null
>> +++ b/scripts/tracetool.py
>> @@ -0,0 +1,585 @@
>> +#!/usr/bin/env python
>> +# Python based tracetool script (Code generator for trace events)
>> +#
>> +# Copyright IBM, Corp. 2011
>> +#
>> +# This work is licensed under the terms of the GNU GPL, version 2. See
>> +# the COPYING file in the top-level directory.
>> +#
>> +#
>> +
>> +import sys
>> +import getopt
>> +
>> +def usage():
>> + print "Tracetool: Generate tracing code for trace events file on stdin"
>> + print "Usage:"
>> + print sys.argv[0], " --backend=[nop|simple|stderr|dtrace|ust] [-h|-c|-d|--stap]"
>> + print '''
>> +Backends:
>> + --nop Tracing disabled
>> + --simple Simple built-in backend
>> + --stderr Stderr built-in backend
>> + --dtrace DTrace/SystemTAP backend
>> + --ust LTTng User Space Tracing backend
>> +
>> +Output formats:
>> + -h Generate .h file
>> + -c Generate .c file
>> + -d Generate .d file (DTrace only)
>> + --stap Generate .stp file (DTrace with SystemTAP only)
>> +
>> +Options:
>> + --binary [path] Full path to QEMU binary
>> + --target-arch [arch] QEMU emulator target arch
>> + --target-type [type] QEMU emulator target type ('system' or 'user')
>> + --probe-prefix [prefix] Prefix for dtrace probe names
>> + (default: qemu-targettype-targetarch)
>> +'''
>> + sys.exit(1)
>> +
>> +def get_name(line, sep='('):
>> + head, sep, tail = line.partition(sep)
>> + return head
>> +
>> +def get_args(line, sep1='(', sep2=')'):
>> + head, sep1, tail = line.partition(sep1)
>> + args, sep2, fmt_str = tail.partition(sep2)
>> + return args
>> +
>> +def get_argnames(line, sep=','):
>> + nfields = 0
>> + str = []
>> + args = get_args(line)
>> + for field in args.split():
>> + nfields = nfields + 1
>> + # Drop pointer star
>> + type, ptr, tail = field.partition('*')
>> + if type != field:
>> + field = tail
>> +
>> + name, sep, tail = field.partition(',')
>> +
>> + if name == field:
>> + continue
>> + str.append(name)
>> + str.append(", ")
>> +
>> + if nfields> 1:
>> + str.append(name)
>> + return ''.join(str)
>> + else:
>> + return ''
>> +
>> +def get_argc(line):
>> + argc = 0
>> + argnames = get_argnames(line)
>> + if argnames:
>> + for name in argnames.split(','):
>> + argc = argc + 1
>> + return argc
>> +
>> +def get_fmt(line, sep=')'):
>> + event, sep, fmt = line.partition(sep)
>> + return fmt
>> +
>> +def calc_sizeofargs(line):
>> + args = get_args(line)
>> + argc = get_argc(line)
>> + strtype = ('const char*', 'char*', 'const char *', 'char *')
>> + str = []
>> + newstr = ""
>> + if argc> 0:
>> + str = args.split(',')
>> + for elem in str:
>> + if elem.lstrip().startswith(strtype): #strings
>> + type, sep, var = elem.rpartition('*')
>> + newstr = newstr+"4 + strlen("+var.lstrip()+") + "
>> + #elif '*' in elem:
>> + # newstr = newstr + "4 + " # pointer vars
>> + else:
>> + #type, sep, var = elem.rpartition(' ')
>> + #newstr = newstr+"sizeof("+type.lstrip()+") + "
>> + newstr = newstr + '8 + '
>> + newstr = newstr + '0' # for last +
>> + return newstr
>> +
>> +
>> +def trace_h_begin():
>> + print '''#ifndef TRACE_H
>> +#define TRACE_H
>> +
>> +/* This file is autogenerated by tracetool, do not edit. */
>> +
>> +#include "qemu-common.h"'''
>> + return
>> +
>> +def trace_h_end():
>> + print '#endif /* TRACE_H */'
>> + return
>> +
>> +def trace_c_begin():
>> + print '/* This file is autogenerated by tracetool, do not edit. */'
>> + return
>> +
>> +def trace_c_end():
>> + # nop, required for trace_gen
>> + return
>> +
>> +def nop_h(events):
>> + print
>> + for event in events:
>> + print '''static inline void trace_%(name)s(%(args)s)
>> +{
>> +}
>> +''' % {
>> + 'name': event.name,
>> + 'args': event.args
>> +}
>> + return
>> +
>> +def nop_c(events):
>> + # nop, reqd for converters
>> + return
>> +
>> +
>> +def simple_h(events):
>> + print '#include "trace/simple.h"'
>> + print
>> + for event in events:
>> + print 'void trace_%(name)s(%(args)s);' % {
>> + 'name': event.name,
>> + 'args': event.args
>> +}
>> + print
>> + print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
>> + print 'extern TraceEvent trace_list[NR_TRACE_EVENTS];'
>> +
>> + return
>> +
>> +def is_string(arg):
>> + strtype = ('const char*', 'char*', 'const char *', 'char *')
>> + if arg.lstrip().startswith(strtype):
>> + return True
>> + else:
>> + return False
>> +
>> +def simple_c(events):
>> + rec_off = 0
>> + print '#include "trace.h"'
>> + print '#include "trace/simple.h"'
>> + print
>> + print 'TraceEvent trace_list[] = {'
>> + print
>> + eventlist = list(events)
>> + for event in eventlist:
>> + print '{.tp_name = "%(name)s", .state=0},' % {
>> + 'name': event.name
>> +}
>> + print
>> + print '};'
>> + print
>> + for event in eventlist:
>> + argc = event.argc
>> + print '''void trace_%(name)s(%(args)s)
>> +{
>> + unsigned int tbuf_idx, rec_off;
>> + uint64_t var64 __attribute__ ((unused));
>> + uint64_t pvar64 __attribute__ ((unused));
>> + uint32_t slen __attribute__ ((unused));
>> +
>> + if (!trace_list[%(event_id)s].state) {
>> + return;
>> + }
>> +''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'event_id': event.num,
>> +}
>> + print '''
>> + tbuf_idx = trace_alloc_record(%(event_id)s, %(sizestr)s);
>> + rec_off = (tbuf_idx + ST_V2_REC_HDR_LEN) %% TRACE_BUF_LEN; /* seek record header */
>> +''' % {'event_id': event.num, 'sizestr': event.sizestr,}
>> +
>> + if argc> 0:
>> + str = event.arglist
>> + for elem in str:
>> + if is_string(elem): # if string
>> + type, sep, var = elem.rpartition('*')
>> + print '''
>> + slen = strlen(%(var)s);
>> + write_to_buffer(rec_off, (uint8_t*)&slen, sizeof(slen));
>> + rec_off += sizeof(slen);''' % {
>> + 'var': var.lstrip()
>> +}
>> + print '''
>> + write_to_buffer(rec_off, (uint8_t*)%(var)s, slen);
>> + rec_off += slen;''' % {
>> + 'var': var.lstrip()
>> +}
>> + elif '*' in elem: # pointer var (not string)
>> + type, sep, var = elem.rpartition('*')
>> + print '''
>> + pvar64 = (uint64_t)(uint64_t*)%(var)s;
>> + write_to_buffer(rec_off, (uint8_t*)&pvar64, sizeof(uint64_t));
>> + rec_off += sizeof(uint64_t);''' % {
>> + 'var': var.lstrip()
>> +}
>> + else: # primitive data type
>> + type, sep, var = elem.rpartition(' ')
>> + print '''
>> + var64 = (uint64_t)%(var)s;
>> + write_to_buffer(rec_off, (uint8_t*)&var64, sizeof(uint64_t));
>> + rec_off += sizeof(uint64_t);''' % {
>> + 'var': var.lstrip()
>> +}
>> + print '''
>> + trace_mark_record_complete(tbuf_idx);'''
>> + print '}'
>> + print
>> +
>> + return
>> +
>> +def stderr_h(events):
>> + print '''#include<stdio.h>
>> +#include "trace/stderr.h"
>> +
>> +extern TraceEvent trace_list[];'''
>> + for event in events:
>> + argnames = event.argnames
>> + if event.argc> 0:
>> + argnames = ', ' + event.argnames
>> + else:
>> + argnames = ''
>> + print '''
>> +static inline void trace_%(name)s(%(args)s)
>> +{
>> + if (trace_list[%(event_num)s].state != 0) {
>> + fprintf(stderr, "%(name)s " %(fmt)s "\\n" %(argnames)s);
>> + }
>> +}''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'event_num': event.num,
>> + 'fmt': event.fmt.rstrip('\n'),
>> + 'argnames': argnames
>> +}
>> + print
>> + print '#define NR_TRACE_EVENTS %d' % (event.num + 1)
>> +
>> +def stderr_c(events):
>> + print '''#include "trace.h"
>> +
>> +TraceEvent trace_list[] = {
>> +'''
>> + for event in events:
>> + print '{.tp_name = "%(name)s", .state=0},' % {
>> + 'name': event.name
>> +}
>> + print
>> + print '};'
>> +
>> +def ust_h(events):
>> + print '''#include<ust/tracepoint.h>
>> +#undef mutex_lock
>> +#undef mutex_unlock
>> +#undef inline
>> +#undef wmb'''
>> +
>> + for event in events:
>> + if event.argc> 0:
>> + print '''
>> +DECLARE_TRACE(ust_%(name)s, TP_PROTO(%(args)s), TP_ARGS(%(argnames)s));
>> +#define trace_%(name)s trace_ust_%(name)s''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'argnames': event.argnames
>> +}
>> + else:
>> + print '''
>> +_DECLARE_TRACEPOINT_NOARGS(ust_%(name)s);
>> +#define trace_%(name)s trace_ust_%(name)s''' % {
>> + 'name': event.name,
>> +}
>> + print
>> + return
>> +
>> +def ust_c(events):
>> + print '''#include<ust/marker.h>
>> +#undef mutex_lock
>> +#undef mutex_unlock
>> +#undef inline
>> +#undef wmb
>> +#include "trace.h"'''
>> + eventlist = list(events)
>> + for event in eventlist:
>> + argnames = event.argnames
>> + if event.argc> 0:
>> + argnames = ', ' + event.argnames
>> + print '''
>> +DEFINE_TRACE(ust_%(name)s);
>> +
>> +static void ust_%(name)s_probe(%(args)s)
>> +{
>> + trace_mark(ust, %(name)s, %(fmt)s%(argnames)s);
>> +}''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'fmt': event.fmt.rstrip('\n'),
>> + 'argnames': argnames
>> +}
>> + else:
>> + print '''
>> +DEFINE_TRACE(ust_%(name)s);
>> +
>> +static void ust_%(name)s_probe(%(args)s)
>> +{
>> + trace_mark(ust, %(name)s, UST_MARKER_NOARGS);
>> +}''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> +}
>> +
>> + # register probes
>> + print '''
>> +static void __attribute__((constructor)) trace_init(void)
>> +{'''
>> + for event in eventlist:
>> + print ' register_trace_ust_%(name)s(ust_%(name)s_probe);' % {
>> + 'name': event.name
>> +}
>> + print '}'
>> +
>> + return
>> +
>> +def dtrace_h(events):
>> + print '#include "trace-dtrace.h"'
>> + print
>> + for event in events:
>> + print '''static inline void trace_%(name)s(%(args)s) {
>> + if (QEMU_%(uppername)s_ENABLED()) {
>> + QEMU_%(uppername)s(%(argnames)s);
>> + }
>> +}
>> +''' % {
>> + 'name': event.name,
>> + 'args': event.args,
>> + 'uppername': event.name.upper(),
>> + 'argnames': event.argnames,
>> +}
>> +
>> +def dtrace_c(events):
>> + return # No need for function definitions in dtrace backend
>> +
>> +def dtrace_d(events):
>> + print 'provider qemu {'
>> + for event in events:
>> + args = event.args
>> +
>> + # DTrace provider syntax expects foo() for empty
>> + # params, not foo(void)
>> + if args == 'void':
>> + args = ''
>> +
>> + # Define prototype for probe arguments
>> + print '''
>> + probe %(name)s(%(args)s);''' % {
>> + 'name': event.name,
>> + 'args': args
>> +}
>> + print
>> + print '};'
>> + return
>> +
>> +def dtrace_stp(events):
>> + for event in events:
>> + # Define prototype for probe arguments
>> + print '''
>> +probe %(probeprefix)s.%(name)s = process("%(binary)s").mark("%(name)s")
>> +{''' % {
>> + 'probeprefix': probeprefix,
>> + 'name': event.name,
>> + 'binary': binary
>> +}
>> + i = 1
>> + if event.argc> 0:
>> + for arg in event.argnames.split(','):
>> + # 'limit' is a reserved keyword
>> + if arg == 'limit':
>> + arg = '_limit'
>> + print ' %s = $arg%d;' % (arg.lstrip(), i)
>> + i += 1
>> + print '}'
>> + print
>> + return
>> +
>> +def trace_stap_begin():
>> + global probeprefix
>> + if backend != "dtrace":
>> + print 'SystemTAP tapset generator not applicable to %s backend' % backend
>> + sys.exit(1)
>> + if binary == "":
>> + print '--binary is required for SystemTAP tapset generator'
>> + sys.exit(1)
>> + if ((probeprefix == "") and (targettype == "")):
>> + print '--target-type is required for SystemTAP tapset generator'
>> + sys.exit(1)
>> + if ((probeprefix == "") and (targetarch == "")):
>> + print '--target-arch is required for SystemTAP tapset generator'
>> + sys.exit(1)
>> + if probeprefix == "":
>> + probeprefix = 'qemu.' + targettype + '.' + targetarch
>> + print '/* This file is autogenerated by tracetool, do not edit. */'
>> + return
>> +
>> +def trace_stap_end():
>> + return #nop, reqd for trace_gen
>> +
>> +def trace_d_begin():
>> + if backend != 'dtrace':
>> + print 'DTrace probe generator not applicable to %s backend' % backend
>> + sys.exit(1)
>> + print '/* This file is autogenerated by tracetool, do not edit. */'
>> +
>> +def trace_d_end():
>> + return #nop, reqd for trace_gen
>> +
>> +
>> +# Registry of backends and their converter functions
>> +converters = {
>> + 'simple': {
>> + 'h': simple_h,
>> + 'c': simple_c,
>> + },
>> +
>> + 'nop': {
>> + 'h': nop_h,
>> + 'c': nop_c,
>> + },
>> +
>> + 'stderr': {
>> + 'h': stderr_h,
>> + 'c': stderr_c,
>> + },
>> +
>> + 'dtrace': {
>> + 'h': dtrace_h,
>> + 'c': dtrace_c,
>> + 'd': dtrace_d,
>> + 'stap': dtrace_stp
>> + },
>> +
>> + 'ust': {
>> + 'h': ust_h,
>> + 'c': ust_c,
>> + },
>> +
>> +}
>> +
>> +# Trace file header and footer code generators
>> +trace_gen = {
>> + 'h': {
>> + 'begin': trace_h_begin,
>> + 'end': trace_h_end,
>> + },
>> + 'c': {
>> + 'begin': trace_c_begin,
>> + 'end': trace_c_end,
>> + },
>> + 'd': {
>> + 'begin': trace_d_begin,
>> + 'end': trace_d_end,
>> + },
>> + 'stap': {
>> + 'begin': trace_stap_begin,
>> + 'end': trace_stap_end,
>> + },
>> +}
>> +
>> +# A trace event
>> +class Event(object):
>> + def __init__(self, num, line):
>> + self.num = num
>> + self.args = get_args(line)
>> + self.arglist = self.args.split(',')
>> + self.name = get_name(line)
>> + self.argc = get_argc(line)
>> + self.argnames = get_argnames(line)
>> + self.sizestr = calc_sizeofargs(line)
>> + self.fmt = get_fmt(line)
>
> This is not not extracting the event properties (e.g., disable). A set of
> strings should suffice.
>
Ok, I had a misunderstanding about 'disable' being removed completely
since all events were enabled by default. I will update the patch as
required. Are there any other properties except 'disable' ?
> Arguments could be converted to an Arguments class (or similar, like
> ArgumentList) and derive the rest from there using methods (e.g., names, types,
> sizestr, arglist, etc.).
>
> If you want, I can send a patch on top of this one with that.
Any improvements are always welcome.
- Harsh
>
>
>> +
>> +# Generator that yields Event objects given a trace-events file object
>> +def read_events(fobj):
>> + event_num = 0
>> + for line in fobj:
>> + if not line.strip():
>> + continue
>> + if line.lstrip().startswith('#'):
>> + continue
>> + yield Event(event_num, line)
>> + event_num += 1
>> +
>> +backend = ""
>> +output = ""
>> +binary = ""
>> +targettype = ""
>> +targetarch = ""
>> +probeprefix = ""
>> +
>> +def main():
>> + global backend, output, binary, targettype, targetarch, probeprefix
>> + supported_backends = ["simple", "nop", "stderr", "dtrace", "ust"]
>> + short_options = "hcd"
>> + long_options = ["stap", "backend=", "binary=", "target-arch=", "target-type=", "probe-prefix=", "list-backends", "check-backend"]
>> + try:
>> + opts, args = getopt.getopt(sys.argv[1:], short_options, long_options)
>> + except getopt.GetoptError, err:
>> + # print help information and exit:
>> + print str(err) # will print something like "option -a not recognized"
>> + usage()
>> + sys.exit(2)
>> + for opt, arg in opts:
>> + if opt == '-h':
>> + output = 'h'
>> + elif opt == '-c':
>> + output = 'c'
>> + elif opt == '-d':
>> + output = 'd'
>> + elif opt == '--stap':
>> + output = 'stap'
>> + elif opt == '--backend':
>> + backend = arg
>> + elif opt == '--binary':
>> + binary = arg
>> + elif opt == '--target-arch':
>> + targetarch = arg
>> + elif opt == '--target-type':
>> + targettype = arg
>> + elif opt == '--probe-prefix':
>> + probeprefix = arg
>> + elif opt == '--list-backends':
>> + print 'simple, nop, stderr, dtrace'
>> + sys.exit(0)
>> + elif opt == "--check-backend":
>> + if any(backend in s for s in supported_backends):
>> + sys.exit(0)
>> + else:
>> + sys.exit(1)
>> + else:
>> + #assert False, "unhandled option"
>> + print "unhandled option: ", opt
>> + usage()
>> +
>> + if backend == "" or output == "":
>> + usage()
>> + sys.exit(0)
>> +
>> + events = read_events(sys.stdin)
>> + trace_gen[output]['begin']()
>> + converters[backend][output](events)
>
> This should use the "disable" property to establish whether to use output or
> "nop".
>
>> + trace_gen[output]['end']()
>> + return
>> +
>> +if __name__ == "__main__":
>> + main()
>> +
>> --
>> 1.7.1.1
>
> Lluis
>
>
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-11 6:38 ` Harsh Bora
@ 2012-01-11 8:46 ` Harsh Bora
2012-01-11 10:50 ` Stefan Hajnoczi
0 siblings, 1 reply; 23+ messages in thread
From: Harsh Bora @ 2012-01-11 8:46 UTC (permalink / raw)
To: Lluís Vilanova, stefanha; +Cc: aneesh.kumar, qemu-devel
On 01/11/2012 12:08 PM, Harsh Bora wrote:
> On 01/11/2012 04:21 AM, Lluís Vilanova wrote:
>> Harsh Prateek Bora writes:
>>
>>> Signed-off-by: Harsh Prateek Bora<harsh@linux.vnet.ibm.com>
>>> ---
>>> Makefile.objs | 6 +-
>>> Makefile.target | 10 +-
>>> configure | 7 +-
>>> scripts/tracetool | 643
>>> --------------------------------------------------
>>> scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
>>> 5 files changed, 597 insertions(+), 654 deletions(-)
>>> delete mode 100755 scripts/tracetool
>>> create mode 100755 scripts/tracetool.py
>>
[...]
>>> +def main():
>>> + global backend, output, binary, targettype, targetarch, probeprefix
>>> + supported_backends = ["simple", "nop", "stderr", "dtrace", "ust"]
>>> + short_options = "hcd"
>>> + long_options = ["stap", "backend=", "binary=", "target-arch=",
>>> "target-type=", "probe-prefix=", "list-backends", "check-backend"]
>>> + try:
>>> + opts, args = getopt.getopt(sys.argv[1:], short_options, long_options)
>>> + except getopt.GetoptError, err:
>>> + # print help information and exit:
>>> + print str(err) # will print something like "option -a not recognized"
>>> + usage()
>>> + sys.exit(2)
>>> + for opt, arg in opts:
>>> + if opt == '-h':
>>> + output = 'h'
>>> + elif opt == '-c':
>>> + output = 'c'
>>> + elif opt == '-d':
>>> + output = 'd'
>>> + elif opt == '--stap':
>>> + output = 'stap'
>>> + elif opt == '--backend':
>>> + backend = arg
>>> + elif opt == '--binary':
>>> + binary = arg
>>> + elif opt == '--target-arch':
>>> + targetarch = arg
>>> + elif opt == '--target-type':
>>> + targettype = arg
>>> + elif opt == '--probe-prefix':
>>> + probeprefix = arg
>>> + elif opt == '--list-backends':
>>> + print 'simple, nop, stderr, dtrace'
>>> + sys.exit(0)
>>> + elif opt == "--check-backend":
>>> + if any(backend in s for s in supported_backends):
>>> + sys.exit(0)
>>> + else:
>>> + sys.exit(1)
>>> + else:
>>> + #assert False, "unhandled option"
>>> + print "unhandled option: ", opt
>>> + usage()
>>> +
>>> + if backend == "" or output == "":
>>> + usage()
>>> + sys.exit(0)
>>> +
>>> + events = read_events(sys.stdin)
>>> + trace_gen[output]['begin']()
>>> + converters[backend][output](events)
>>
>> This should use the "disable" property to establish whether to use
>> output or
>> "nop".
Will it be better to again break converters to their begin,
process_line, end counterparts and call respective converters
accordingly for enabled/disabled events, or let all the backends handle
disabled events on their own ?
Stefan ?
- Harsh
>>
>>> + trace_gen[output]['end']()
>>> + return
>>> +
>>> +if __name__ == "__main__":
>>> + main()
>>> +
>>> --
>>> 1.7.1.1
>>
>> Lluis
>>
>>
>
>
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-11 6:25 ` Harsh Bora
@ 2012-01-11 10:03 ` Stefan Hajnoczi
0 siblings, 0 replies; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-11 10:03 UTC (permalink / raw)
To: Harsh Bora
Cc: aneesh.kumar, vilanova, mathieu.desnoyers, stefanha, qemu-devel
On Wed, Jan 11, 2012 at 6:25 AM, Harsh Bora <harsh@linux.vnet.ibm.com> wrote:
> Also, please confirm, whether I should work on top for qemu.git or your
> tracing branch on repo.or.cz/stefanha.git ?
Please use https://github.com/stefanha/qemu/tree/tracing. (I also
just sent a patch to update the git URL in MAINTAINERS.)
Stefan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
` (2 preceding siblings ...)
2012-01-10 22:51 ` Lluís Vilanova
@ 2012-01-11 10:07 ` Stefan Hajnoczi
3 siblings, 0 replies; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-11 10:07 UTC (permalink / raw)
To: Harsh Prateek Bora
Cc: vilanova, mathieu.desnoyers, qemu-devel, stefanha, aneesh.kumar
On Tue, Jan 10, 2012 at 10:59 AM, Harsh Prateek Bora
<harsh@linux.vnet.ibm.com> wrote:
> +# Generator that yields Event objects given a trace-events file object
> +def read_events(fobj):
> + event_num = 0
> + for line in fobj:
> + if not line.strip():
> + continue
> + if line.lstrip().startswith('#'):
> + continue
> + yield Event(event_num, line)
> + event_num += 1
Please use 4 space indentation. There is also a use of tab on the
converters['simple']['c'] = simple_c line earlier on.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-11 8:46 ` Harsh Bora
@ 2012-01-11 10:50 ` Stefan Hajnoczi
0 siblings, 0 replies; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-11 10:50 UTC (permalink / raw)
To: Harsh Bora; +Cc: aneesh.kumar, qemu-devel, Lluís Vilanova, stefanha
On Wed, Jan 11, 2012 at 8:46 AM, Harsh Bora <harsh@linux.vnet.ibm.com> wrote:
> On 01/11/2012 12:08 PM, Harsh Bora wrote:
>>
>> On 01/11/2012 04:21 AM, Lluís Vilanova wrote:
>>>
>>> Harsh Prateek Bora writes:
>>>
>>>> Signed-off-by: Harsh Prateek Bora<harsh@linux.vnet.ibm.com>
>>>> ---
>>>> Makefile.objs | 6 +-
>>>> Makefile.target | 10 +-
>>>> configure | 7 +-
>>>> scripts/tracetool | 643
>>>> --------------------------------------------------
>>>> scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
>>>> 5 files changed, 597 insertions(+), 654 deletions(-)
>>>> delete mode 100755 scripts/tracetool
>>>> create mode 100755 scripts/tracetool.py
>>>
>>>
>
> [...]
>
>>>> +def main():
>>>> + global backend, output, binary, targettype, targetarch, probeprefix
>>>> + supported_backends = ["simple", "nop", "stderr", "dtrace", "ust"]
>>>> + short_options = "hcd"
>>>> + long_options = ["stap", "backend=", "binary=", "target-arch=",
>>>> "target-type=", "probe-prefix=", "list-backends", "check-backend"]
>>>> + try:
>>>> + opts, args = getopt.getopt(sys.argv[1:], short_options, long_options)
>>>> + except getopt.GetoptError, err:
>>>> + # print help information and exit:
>>>> + print str(err) # will print something like "option -a not recognized"
>>>> + usage()
>>>> + sys.exit(2)
>>>> + for opt, arg in opts:
>>>> + if opt == '-h':
>>>> + output = 'h'
>>>> + elif opt == '-c':
>>>> + output = 'c'
>>>> + elif opt == '-d':
>>>> + output = 'd'
>>>> + elif opt == '--stap':
>>>> + output = 'stap'
>>>> + elif opt == '--backend':
>>>> + backend = arg
>>>> + elif opt == '--binary':
>>>> + binary = arg
>>>> + elif opt == '--target-arch':
>>>> + targetarch = arg
>>>> + elif opt == '--target-type':
>>>> + targettype = arg
>>>> + elif opt == '--probe-prefix':
>>>> + probeprefix = arg
>>>> + elif opt == '--list-backends':
>>>> + print 'simple, nop, stderr, dtrace'
>>>> + sys.exit(0)
>>>> + elif opt == "--check-backend":
>>>> + if any(backend in s for s in supported_backends):
>>>> + sys.exit(0)
>>>> + else:
>>>> + sys.exit(1)
>>>> + else:
>>>> + #assert False, "unhandled option"
>>>> + print "unhandled option: ", opt
>>>> + usage()
>>>> +
>>>> + if backend == "" or output == "":
>>>> + usage()
>>>> + sys.exit(0)
>>>> +
>>>> + events = read_events(sys.stdin)
>>>> + trace_gen[output]['begin']()
>>>> + converters[backend][output](events)
>>>
>>>
>>> This should use the "disable" property to establish whether to use
>>> output or
>>> "nop".
>
>
> Will it be better to again break converters to their begin, process_line,
> end counterparts and call respective converters accordingly for
> enabled/disabled events, or let all the backends handle disabled events on
> their own ?
>
> Stefan ?
I suggest adding a Event.properties field. For most events it will be
[] but for disabled events it will be ['disable']. In the future we
could support new keywords.
Then we can filter out the disabled events in main():
disabled_events, enabled_events = [], []
for e in read_events(sys.stdin):
if 'disable' in e.properties:
disabled_events.append(e)
else:
enabled_events.append(e)
trace_gen[output]['begin']()
converters['nop'][output](disabled_events)
converters[backend][output](enabled_events)
trace_gen[output]['end']()
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 3/3] simpletrace.py: updated log reader script to handle new log format
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 3/3] simpletrace.py: updated log reader script to handle new log format Harsh Prateek Bora
@ 2012-01-11 12:30 ` Stefan Hajnoczi
0 siblings, 0 replies; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-11 12:30 UTC (permalink / raw)
To: Harsh Prateek Bora
Cc: vilanova, mathieu.desnoyers, qemu-devel, stefanha, aneesh.kumar
On Tue, Jan 10, 2012 at 10:59 AM, Harsh Prateek Bora
<harsh@linux.vnet.ibm.com> wrote:
> diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
This file is primarily a Python module for writing trace analysis
scripts. The Formatter is a useful code example that shows how to use
the module. This change breaks the module API and turns this file
basically just into the Formatter. Please don't do that.
When processing v2 files the trace record arguments passed to
Analyzer.catchall() or dedicated event handler methods can now also be
strings, not just ints. That's the only API change that is required.
> +def get_event_argtypes(fobj):
> + """Parse a trace-events file into {event_num: (name, type arg, ...)}."""
> +
> + events = {dropped_event_id: ('name', 'args')}
> + event_num = 0
> + for line in fobj:
> + m = event_re.match(line.strip())
> + if m is None:
> + continue
> +
> + disable, name, args = m.groups()
> + events[event_num] = tuple(args.split(','))
> + event_num += 1
> + return events
It would be nice to share Event with tracetool.py instead of
duplicating trace-events parsing. If you want Event can live in its
own traceevent.py module.
> +def process_event(event_id, fobj):
> + params = etypes[event_id]
> + for elem in params:
> + if is_string(elem):
> + l = fobj.read(4)
> + (len,) = struct.unpack('=L', l)
> + s = fobj.read(len)
> + sfmt = `len`+'s'
> + (str,) = struct.unpack_from(sfmt, s)
s == str, there's no need to unpack
> + type, sep, var = elem.rpartition('*')
Event should handle trace-events parsing, we shouldn't sprinkle the
parsing into all code that uses trace-events.
> + print '%(arg)s=%(val)s' % { 'arg': var.lstrip(), 'val': str },
> + elif '*' in elem:
> + (value,) = struct.unpack('=Q', fobj.read(8))
> + type, sep, var = elem.rpartition('*')
> + print '%(arg)s=0x%(val)u' % { 'arg': var.lstrip(), 'val': value },
> + else:
> + (value,) = struct.unpack('=Q', fobj.read(8))
> + type, sep, var = elem.rpartition(' ')
> + print '%(arg)s=%(val)u' % { 'arg': var.lstrip(), 'val': value },
The existing simpletrace.py Formatter will use 0x%x for all fields. I
suggest keeping it that way unless you want to use the event's format
string, which is might be doable (though you'd need to convert '%p' to
'%#x').
> + print
> + return
> +
> +etypes = get_event_argtypes(open(sys.argv[1], 'r'))
Parsing trace-events...
> +def processv2(fobj):
> + '''Process simpletrace v2 log trace records'''
> + events = parse_events(open(sys.argv[1], 'r'))
...multiple times in different ways is not good. Please implement an
Event class that handles the file format parsing and is shared between
simpletrace.py and tracetool.py.
> + #print events
> + max_events = len(events) - 1
> + last_timestamp = None
> + while True:
> + # read record header
> + rechdr = read_header(fobj)
> + if rechdr is None:
> + print "No more records"
debugging?
> + break
> +
> + if rechdr[0] >= max_events:
> + print "Invalid Event ID found, Trace Log may be corrupted !!!"
> + sys.exit(1)
> +
> + if last_timestamp is None:
> + last_timestamp = rechdr[1]
> + delta_ns = rechdr[1] - last_timestamp
> + last_timestamp = rechdr[1]
> +
> + print events[rechdr[0]][0], '%0.3f' % (delta_ns / 1000.0),
simpletrace is a module that analysis scripts use, it should not print
anything. The prints belong in the Formatter() class which does
pretty-printing and is executed when simpletrace.py is executed as a
program.
> + # read data
> + # process_event(rec[0], fobj)
> + # rechdr[2] is record length (including header)
> + #print etypes[rechdr[0]]
> + #data = fobj.read(rechdr[2] - header_len)
> + process_event(rechdr[0], fobj)
> +
> class Analyzer(object):
> """A trace file analyzer which processes trace records.
>
> @@ -90,8 +165,6 @@ def process(events, log, analyzer):
> """Invoke an analyzer on each event in a log."""
> if isinstance(events, str):
> events = parse_events(open(events, 'r'))
> - if isinstance(log, str):
> - log = open(log, 'rb')
Removing this breaks existing analysis scripts that use process().
Parsing the header should be part of read_trace_file(), we can raise
an exception if the file format is unsupported.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 21:45 ` Lluís Vilanova
@ 2012-01-11 17:14 ` Stefan Hajnoczi
0 siblings, 0 replies; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-11 17:14 UTC (permalink / raw)
To: Lluís Vilanova
Cc: Harsh Prateek Bora, mathieu.desnoyers, aneesh.kumar, stefanha,
qemu-devel
2012/1/10 Lluís Vilanova <vilanova@ac.upc.edu>:
> Harsh Prateek Bora writes:
>
>> Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
>> ---
>> Makefile.objs | 6 +-
>> Makefile.target | 10 +-
>> configure | 7 +-
>> scripts/tracetool | 643 --------------------------------------------------
>> scripts/tracetool.py | 585 +++++++++++++++++++++++++++++++++++++++++++++
>> 5 files changed, 597 insertions(+), 654 deletions(-)
>> delete mode 100755 scripts/tracetool
>> create mode 100755 scripts/tracetool.py
>
> Cannot be applied on top of Stefan's tracing branch (AFAIK, it has only one
> commit pending merge into upstream).
>
> Stefan, are you waiting for more patches to accumulate before merging your
> branch, or is it just waiting for a prediodical merge?
Both. I should have sent a pull request for the single commit but
forgot. Now I'm going to wait for the simpletrace v2 patches before I
send the next pull request.
Stefan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py
2012-01-10 22:51 ` Lluís Vilanova
2012-01-11 6:38 ` Harsh Bora
@ 2012-01-12 9:33 ` Stefan Hajnoczi
1 sibling, 0 replies; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-12 9:33 UTC (permalink / raw)
To: Lluís Vilanova
Cc: Harsh Prateek Bora, aneesh.kumar, stefanha, qemu-devel
2012/1/10 Lluís Vilanova <vilanova@ac.upc.edu>:
> Harsh Prateek Bora writes:
>> +class Event(object):
>> + def __init__(self, num, line):
>> + self.num = num
>> + self.args = get_args(line)
>> + self.arglist = self.args.split(',')
>> + self.name = get_name(line)
>> + self.argc = get_argc(line)
>> + self.argnames = get_argnames(line)
>> + self.sizestr = calc_sizeofargs(line)
>> + self.fmt = get_fmt(line)
>
> This is not not extracting the event properties (e.g., disable). A set of
> strings should suffice.
>
> Arguments could be converted to an Arguments class (or similar, like
> ArgumentList) and derive the rest from there using methods (e.g., names, types,
> sizestr, arglist, etc.).
Yes, that would be nice. This will separate the trace-events parsing
from the rest of the program, which can use the Event/Argument
interface instead of parsing strings.
Stefan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-10 16:41 ` Stefan Hajnoczi
@ 2012-01-18 9:14 ` Harsh Bora
2012-01-18 10:31 ` Stefan Hajnoczi
0 siblings, 1 reply; 23+ messages in thread
From: Harsh Bora @ 2012-01-18 9:14 UTC (permalink / raw)
To: Stefan Hajnoczi, stefanha; +Cc: vilanova, qemu-devel, aneesh.kumar
On 01/10/2012 10:11 PM, Stefan Hajnoczi wrote:
> On Tue, Jan 10, 2012 at 10:59 AM, Harsh Prateek Bora
> <harsh@linux.vnet.ibm.com> wrote:
>> Advantages over existing simpletrace backend:
>> - More than 6 elements (vitually unlimited) arguments can be traced.
>> - This allows to trace strings (variable size element) as well.
>>
>> Signed-off-by: Harsh Prateek Bora<harsh@linux.vnet.ibm.com>
>> ---
>> monitor.c | 2 +-
>> trace/simple.c | 178 ++++++++++++++++++++------------------------------------
>> trace/simple.h | 31 ++++++++--
>> 3 files changed, 88 insertions(+), 123 deletions(-)
>>
>> diff --git a/monitor.c b/monitor.c
>> index ffda0fe..b6f85d1 100644
>> --- a/monitor.c
>> +++ b/monitor.c
>> @@ -945,7 +945,7 @@ static void do_info_cpu_stats(Monitor *mon)
>> #if defined(CONFIG_TRACE_SIMPLE)
>> static void do_info_trace(Monitor *mon)
>> {
>> - st_print_trace((FILE *)mon,&monitor_fprintf);
>> + /* FIXME: st_print_trace((FILE *)mon,&monitor_fprintf); */
>
> This command is only available from the human monitor. It's not very
> useful because it historically hasn't been able to pretty-print events
> or show them in the right order (we use a ringbuffer but it prints
> them out from index 0).
>
> Therefore, I don't think we're under any obligation to keep this
> command around. No one has complained about it's limitations - I
> think this is a sign that no one has used it. I'd be okay with a
> patch that removes it.
>
>> }
>> #endif
>>
>> diff --git a/trace/simple.c b/trace/simple.c
>> index b639dda..65cafe2 100644
>> --- a/trace/simple.c
>> +++ b/trace/simple.c
>> @@ -27,7 +27,7 @@
>> #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL
>>
>> /** Trace file version number, bump if format changes */
>> -#define HEADER_VERSION 0
>> +#define HEADER_VERSION 2
>>
>> /** Records were dropped event ID */
>> #define DROPPED_EVENT_ID (~(uint64_t)0 - 1)
>> @@ -35,23 +35,6 @@
>> /** Trace record is valid */
>> #define TRACE_RECORD_VALID ((uint64_t)1<< 63)
>>
>> -/** Trace buffer entry */
>> -typedef struct {
>> - uint64_t event;
>> - uint64_t timestamp_ns;
>> - uint64_t x1;
>> - uint64_t x2;
>> - uint64_t x3;
>> - uint64_t x4;
>> - uint64_t x5;
>> - uint64_t x6;
>> -} TraceRecord;
>> -
>> -enum {
>> - TRACE_BUF_LEN = 4096,
>> - TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
>> -};
>> -
>> /*
>> * Trace records are written out by a dedicated thread. The thread waits for
>> * records to become available, writes them out, and then waits again.
>> @@ -62,11 +45,12 @@ static GCond *trace_empty_cond;
>> static bool trace_available;
>> static bool trace_writeout_enabled;
>>
>> -static TraceRecord trace_buf[TRACE_BUF_LEN];
>> +uint8_t trace_buf[TRACE_BUF_LEN];
>> static unsigned int trace_idx;
>> static FILE *trace_fp;
>> static char *trace_file_name = NULL;
>>
>> +
>
> Spurious newline.
>
>> /**
>> * Read a trace record from the trace buffer
>> *
>> @@ -75,16 +59,19 @@ static char *trace_file_name = NULL;
>> *
>> * Returns false if the record is not valid.
>> */
>> -static bool get_trace_record(unsigned int idx, TraceRecord *record)
>> +static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
>> {
>> - if (!(trace_buf[idx].event& TRACE_RECORD_VALID)) {
>> + TraceRecord *record = (TraceRecord *)&trace_buf[idx];
>> + if (!(record->event& TRACE_RECORD_VALID)) {
>> return false;
>> }
>>
>> __sync_synchronize(); /* read memory barrier before accessing record */
>>
>> - *record = trace_buf[idx];
>> - record->event&= ~TRACE_RECORD_VALID;
>> + *recordptr = g_malloc(record->length);
>> + /* make a copy of record to avoid being overwritten */
>> + memcpy(*recordptr, record, record->length);
>> + (*recordptr)->event&= ~TRACE_RECORD_VALID;
>> return true;
>> }
>>
>> @@ -106,6 +93,47 @@ static void flush_trace_file(bool wait)
>> g_static_mutex_unlock(&trace_lock);
>> }
>>
>> +unsigned int trace_alloc_record(TraceEventID event, uint32_t datasize)
>> +{
>> + unsigned int idx, rec_off;
>> + uint32_t rec_len = ST_V2_REC_HDR_LEN + datasize;
>> + uint64_t timestamp_ns = get_clock();
>> +
>> + idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) % TRACE_BUF_LEN;
>> + rec_off = idx;
>> + write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
>> + rec_off += sizeof(event);
>> + write_to_buffer(rec_off, (uint8_t*)×tamp_ns, sizeof(timestamp_ns));
>> + rec_off += sizeof(timestamp_ns);
>> + write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len));
>> + rec_off += sizeof(rec_len);
>> + return idx;
>> +}
>> +
>> +void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size)
>> +{
>> + uint32_t x = 0;
>> + while (x< size)
>> + {
>> + if (idx>= TRACE_BUF_LEN) {
>> + idx = idx % TRACE_BUF_LEN;
>> + }
>> + trace_buf[idx++] = dataptr[x++];
>> + }
>> +}
>> +
>> +void trace_mark_record_complete(unsigned int idx)
>> +{
>> + TraceRecord *record = (TraceRecord*)&trace_buf[idx];
>> +
>> + __sync_synchronize(); /* write barrier before marking as valid */
>> + record->event |= TRACE_RECORD_VALID;
>> +
>> + if (idx> TRACE_BUF_FLUSH_THRESHOLD) {
>> + flush_trace_file(false);
>> + }
>
> This looks suspicious. We want to kick the writeout thread when the
> buffer reaches the threshold but not repeatedly after that. Also
> because it's a ring buffer idx could "start" above the threshold.
>
> Perhaps something like:
> if (idx> TRACE_BUF_FLUSH_THRESHOLD&& old_idx<= TRACE_BUF_FLUSH_THRESHOLD) {
> flush_trace_file(false);
> }
>
>> +}
>> +
>> static void wait_for_trace_records_available(void)
>> {
>> g_static_mutex_lock(&trace_lock);
>> @@ -120,7 +148,7 @@ static void wait_for_trace_records_available(void)
>>
>> static gpointer writeout_thread(gpointer opaque)
>> {
>> - TraceRecord record;
>> + TraceRecord record, *recordptr;
>> unsigned int writeout_idx = 0;
>> unsigned int num_available, idx;
>> size_t unused __attribute__ ((unused));
>> @@ -130,19 +158,20 @@ static gpointer writeout_thread(gpointer opaque)
>>
>> num_available = trace_idx - writeout_idx;
>> if (num_available> TRACE_BUF_LEN) {
>> - record = (TraceRecord){
>> - .event = DROPPED_EVENT_ID,
>> - .x1 = num_available,
>> - };
>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>> + record.event = DROPPED_EVENT_ID,
>> + record.length = num_available,
>
> Please don't use .length for the number of bytes dropped because this
> makes life harder for parsing scripts like simpletrace.py. They would
> need a special case to check for DROPPED_EVENT_ID and then treat
> .length as an argument. Instead the number of bytes should be an
> argument.
>
> Also, by removing the struct literal assignment you lose the automatic
> zeroing of fields. We'll write out junk data - it would be nicer to
> clear it.
>
>> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
>> writeout_idx += num_available;
>> }
>>
>> idx = writeout_idx % TRACE_BUF_LEN;
>> - while (get_trace_record(idx,&record)) {
>> - trace_buf[idx].event = 0; /* clear valid bit */
>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>> - idx = ++writeout_idx % TRACE_BUF_LEN;
>> + while (get_trace_record(idx,&recordptr)) {
>> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
>> + writeout_idx += recordptr->length;
>> + g_free(recordptr);
>> + recordptr = (TraceRecord *)&trace_buf[idx];
>> + recordptr->event = 0;
>> + idx = writeout_idx % TRACE_BUF_LEN;
>> }
>
> I'm wondering if it's worth using a different approach here. Writing
> out individual records has bothered me.
>
> If we have a second buffer, as big as trace_buf[], then a function can
> copy out all records and make them available in trace_buf again:
>
> /**
> * Copy completed trace records out of the ring buffer
> *
> * @idx offset into trace_buf[]
> * @buf destination buffer
> * @len size of destination buffer
> * @ret the number of bytes consumed
> */
> size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
>
> That means consume gobbles up as many records as it can:
> * Until it reaches an invalid record which has not been written yet
> * Until it reaches the end of trace_buf[], the caller can call again
> with idx wrapped to 0
>
> After copying into buf[] it clears the valid bit in trace_buf[].
>
> Then the loop which calls consume_trace_records() does a single
> fwrite(3) and increments idx/writeout_idx.
>
> The advantage to this is that we write many records in one go and I
> think it splits up the writeout steps a little nicer than what we've
> previously done.
>
I think this optimization can be introduced as a separate patch later.
Let me know if you think otherwise.
>>
>> fflush(trace_fp);
>> @@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
>> static const TraceRecord header = {
>> .event = HEADER_EVENT_ID,
>> .timestamp_ns = HEADER_MAGIC,
>> - .x1 = HEADER_VERSION,
>> + .length = HEADER_VERSION,
>
> Hmm...this is kind of ugly (see comment about using .length above) but
> in this case most parsers will have a special-case anyway to check the
> magic number. We need to use the .length field because historically
> that's where the version is located.
>
So, lets keep the version here only, right ?
- Harsh
>> +/* Interfaces for simpletrace v2 */
>
> Please drop this comment. All trace/simple.[ch] code is for v2, this
> makes it seems like we support both versions at the same time.
>
>> +
>> +/** Trace buffer entry */
>> +typedef struct {
>> + uint64_t event; /* TraceEventID */
>> + uint64_t timestamp_ns;
>> + uint32_t length; /* in bytes */
>> + uint32_t reserved; /* unused */
>> + uint8_t arguments[]; /* arguments position affects ST_V2_REC_HDR_LEN */
>> +} TraceRecord;
>
> Does this need to be visible? I think it can live in trace/simple.c
>
>> +
>> +#define ST_V2_REC_HDR_LEN 24
>
> Does not need to be visible. Also why calculate manually, instead of
> a macro I would use sizeof(TraceRecord) (the array without elements is
> not counted by sizeof).
>
>> +
>> +enum {
>> + TRACE_BUF_LEN = 4096 * 64,
>> + TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4,
>> +};
>
> Does not need to be visible.
>
>> +
>> +extern uint8_t trace_buf[TRACE_BUF_LEN];
>
> Does not need to be visible.
>
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-18 9:14 ` Harsh Bora
@ 2012-01-18 10:31 ` Stefan Hajnoczi
2012-01-18 10:41 ` Harsh Bora
0 siblings, 1 reply; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-18 10:31 UTC (permalink / raw)
To: Harsh Bora; +Cc: aneesh.kumar, vilanova, stefanha, qemu-devel
On Wed, Jan 18, 2012 at 9:14 AM, Harsh Bora <harsh@linux.vnet.ibm.com> wrote:
> On 01/10/2012 10:11 PM, Stefan Hajnoczi wrote:
>>> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
>>> writeout_idx += num_available;
>>> }
>>>
>>> idx = writeout_idx % TRACE_BUF_LEN;
>>> - while (get_trace_record(idx,&record)) {
>>> - trace_buf[idx].event = 0; /* clear valid bit */
>>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>>> - idx = ++writeout_idx % TRACE_BUF_LEN;
>>> + while (get_trace_record(idx,&recordptr)) {
>>> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
>>> + writeout_idx += recordptr->length;
>>> + g_free(recordptr);
>>> + recordptr = (TraceRecord *)&trace_buf[idx];
>>>
>>> + recordptr->event = 0;
>>> + idx = writeout_idx % TRACE_BUF_LEN;
>>> }
>>
>>
>> I'm wondering if it's worth using a different approach here. Writing
>> out individual records has bothered me.
>>
>> If we have a second buffer, as big as trace_buf[], then a function can
>> copy out all records and make them available in trace_buf again:
>>
>> /**
>> * Copy completed trace records out of the ring buffer
>> *
>> * @idx offset into trace_buf[]
>> * @buf destination buffer
>> * @len size of destination buffer
>> * @ret the number of bytes consumed
>> */
>> size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
>>
>> That means consume gobbles up as many records as it can:
>> * Until it reaches an invalid record which has not been written yet
>> * Until it reaches the end of trace_buf[], the caller can call again
>> with idx wrapped to 0
>>
>> After copying into buf[] it clears the valid bit in trace_buf[].
>>
>> Then the loop which calls consume_trace_records() does a single
>> fwrite(3) and increments idx/writeout_idx.
>>
>> The advantage to this is that we write many records in one go and I
>> think it splits up the writeout steps a little nicer than what we've
>> previously done.
>>
>
> I think this optimization can be introduced as a separate patch later.
> Let me know if you think otherwise.
Yes, that could be done later. However there is something incorrect
here. Threads will continue to write trace records into the
ringbuffer while the write-out thread is doing I/O. Think about what
happens when threads overtake the write-out index modulo ringbuffer
size. Since records are variable-length the write-out thread's next
index could point into the middle of an overwritten record. And that
means the ->length field is junk - we may crash if we use it.
>>>
>>> fflush(trace_fp);
>>> @@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
>>> static const TraceRecord header = {
>>> .event = HEADER_EVENT_ID,
>>> .timestamp_ns = HEADER_MAGIC,
>>> - .x1 = HEADER_VERSION,
>>> + .length = HEADER_VERSION,
>>
>>
>> Hmm...this is kind of ugly (see comment about using .length above) but
>> in this case most parsers will have a special-case anyway to check the
>> magic number. We need to use the .length field because historically
>> that's where the version is located.
>>
>
> So, lets keep the version here only, right ?
Yes, it's necessary to do .length = HEADER_VERSION.
Stefan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-18 10:31 ` Stefan Hajnoczi
@ 2012-01-18 10:41 ` Harsh Bora
2012-01-18 10:52 ` Harsh Bora
0 siblings, 1 reply; 23+ messages in thread
From: Harsh Bora @ 2012-01-18 10:41 UTC (permalink / raw)
To: Stefan Hajnoczi; +Cc: qemu-devel, aneesh.kumar, stefanha, vilanova
On 01/18/2012 04:01 PM, Stefan Hajnoczi wrote:
> On Wed, Jan 18, 2012 at 9:14 AM, Harsh Bora<harsh@linux.vnet.ibm.com> wrote:
>> On 01/10/2012 10:11 PM, Stefan Hajnoczi wrote:
>>>> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
>>>> writeout_idx += num_available;
>>>> }
>>>>
>>>> idx = writeout_idx % TRACE_BUF_LEN;
>>>> - while (get_trace_record(idx,&record)) {
>>>> - trace_buf[idx].event = 0; /* clear valid bit */
>>>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>>>> - idx = ++writeout_idx % TRACE_BUF_LEN;
>>>> + while (get_trace_record(idx,&recordptr)) {
>>>> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
>>>> + writeout_idx += recordptr->length;
>>>> + g_free(recordptr);
>>>> + recordptr = (TraceRecord *)&trace_buf[idx];
>>>>
>>>> + recordptr->event = 0;
>>>> + idx = writeout_idx % TRACE_BUF_LEN;
>>>> }
>>>
>>>
>>> I'm wondering if it's worth using a different approach here. Writing
>>> out individual records has bothered me.
>>>
>>> If we have a second buffer, as big as trace_buf[], then a function can
>>> copy out all records and make them available in trace_buf again:
>>>
>>> /**
>>> * Copy completed trace records out of the ring buffer
>>> *
>>> * @idx offset into trace_buf[]
>>> * @buf destination buffer
>>> * @len size of destination buffer
>>> * @ret the number of bytes consumed
>>> */
>>> size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
>>>
>>> That means consume gobbles up as many records as it can:
>>> * Until it reaches an invalid record which has not been written yet
>>> * Until it reaches the end of trace_buf[], the caller can call again
>>> with idx wrapped to 0
>>>
>>> After copying into buf[] it clears the valid bit in trace_buf[].
>>>
>>> Then the loop which calls consume_trace_records() does a single
>>> fwrite(3) and increments idx/writeout_idx.
>>>
>>> The advantage to this is that we write many records in one go and I
>>> think it splits up the writeout steps a little nicer than what we've
>>> previously done.
>>>
>>
>> I think this optimization can be introduced as a separate patch later.
>> Let me know if you think otherwise.
>
> Yes, that could be done later. However there is something incorrect
> here. Threads will continue to write trace records into the
> ringbuffer while the write-out thread is doing I/O. Think about what
> happens when threads overtake the write-out index modulo ringbuffer
> size. Since records are variable-length the write-out thread's next
> index could point into the middle of an overwritten record. And that
> means the ->length field is junk - we may crash if we use it.
In case of overwritten records, the valid bit of event id will also be
overwritten, and therefore we will not consider that record. Moreover,
the writeout thread will further get to know that some events were
dropped and will start with the latest trace_idx, right ?
However, to handle the extreme rare case of having an overwritten value
such that its valid bit appears to be set, we can put a check for <
NR_TRACE_EVENTS. Even better to have a magic byte for events also ?
Harsh
>
>>>>
>>>> fflush(trace_fp);
>>>> @@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
>>>> static const TraceRecord header = {
>>>> .event = HEADER_EVENT_ID,
>>>> .timestamp_ns = HEADER_MAGIC,
>>>> - .x1 = HEADER_VERSION,
>>>> + .length = HEADER_VERSION,
>>>
>>>
>>> Hmm...this is kind of ugly (see comment about using .length above) but
>>> in this case most parsers will have a special-case anyway to check the
>>> magic number. We need to use the .length field because historically
>>> that's where the version is located.
>>>
>>
>> So, lets keep the version here only, right ?
>
> Yes, it's necessary to do .length = HEADER_VERSION.
>
> Stefan
>
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-18 10:41 ` Harsh Bora
@ 2012-01-18 10:52 ` Harsh Bora
2012-01-18 10:59 ` Stefan Hajnoczi
0 siblings, 1 reply; 23+ messages in thread
From: Harsh Bora @ 2012-01-18 10:52 UTC (permalink / raw)
To: Stefan Hajnoczi; +Cc: vilanova, qemu-devel, stefanha, aneesh.kumar
On 01/18/2012 04:11 PM, Harsh Bora wrote:
> On 01/18/2012 04:01 PM, Stefan Hajnoczi wrote:
>> On Wed, Jan 18, 2012 at 9:14 AM, Harsh Bora<harsh@linux.vnet.ibm.com>
>> wrote:
>>> On 01/10/2012 10:11 PM, Stefan Hajnoczi wrote:
>>>>> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
>>>>> writeout_idx += num_available;
>>>>> }
>>>>>
>>>>> idx = writeout_idx % TRACE_BUF_LEN;
>>>>> - while (get_trace_record(idx,&record)) {
>>>>> - trace_buf[idx].event = 0; /* clear valid bit */
>>>>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>>>>> - idx = ++writeout_idx % TRACE_BUF_LEN;
>>>>> + while (get_trace_record(idx,&recordptr)) {
>>>>> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
>>>>> + writeout_idx += recordptr->length;
>>>>> + g_free(recordptr);
>>>>> + recordptr = (TraceRecord *)&trace_buf[idx];
>>>>>
>>>>> + recordptr->event = 0;
>>>>> + idx = writeout_idx % TRACE_BUF_LEN;
>>>>> }
>>>>
>>>>
>>>> I'm wondering if it's worth using a different approach here. Writing
>>>> out individual records has bothered me.
>>>>
>>>> If we have a second buffer, as big as trace_buf[], then a function can
>>>> copy out all records and make them available in trace_buf again:
>>>>
>>>> /**
>>>> * Copy completed trace records out of the ring buffer
>>>> *
>>>> * @idx offset into trace_buf[]
>>>> * @buf destination buffer
>>>> * @len size of destination buffer
>>>> * @ret the number of bytes consumed
>>>> */
>>>> size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
>>>>
>>>> That means consume gobbles up as many records as it can:
>>>> * Until it reaches an invalid record which has not been written yet
>>>> * Until it reaches the end of trace_buf[], the caller can call again
>>>> with idx wrapped to 0
>>>>
>>>> After copying into buf[] it clears the valid bit in trace_buf[].
>>>>
>>>> Then the loop which calls consume_trace_records() does a single
>>>> fwrite(3) and increments idx/writeout_idx.
>>>>
>>>> The advantage to this is that we write many records in one go and I
>>>> think it splits up the writeout steps a little nicer than what we've
>>>> previously done.
>>>>
>>>
>>> I think this optimization can be introduced as a separate patch later.
>>> Let me know if you think otherwise.
>>
>> Yes, that could be done later. However there is something incorrect
>> here. Threads will continue to write trace records into the
>> ringbuffer while the write-out thread is doing I/O. Think about what
>> happens when threads overtake the write-out index modulo ringbuffer
>> size. Since records are variable-length the write-out thread's next
>> index could point into the middle of an overwritten record. And that
>> means the ->length field is junk - we may crash if we use it.
>
> In case of overwritten records, the valid bit of event id will also be
> overwritten, and therefore we will not consider that record. Moreover,
> the writeout thread will further get to know that some events were
> dropped and will start with the latest trace_idx, right ?
>
> However, to handle the extreme rare case of having an overwritten value
> such that its valid bit appears to be set, we can put a check for <
> NR_TRACE_EVENTS. Even better to have a magic byte for events also ?
>
> Harsh
Also, I just realized that we need to put buffer boundary checks while
copying a trace record:
>> -static bool get_trace_record(unsigned int idx, TraceRecord *record)
>> +static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
>> {
>> - if (!(trace_buf[idx].event& TRACE_RECORD_VALID)) {
>> + TraceRecord *record = (TraceRecord *)&trace_buf[idx];
>> + if (!(record->event& TRACE_RECORD_VALID)) {
>> return false;
>> }
>>
>> __sync_synchronize(); /* read memory barrier before accessing
record */
>>
>> - *record = trace_buf[idx];
>> - record->event&= ~TRACE_RECORD_VALID;
>> + *recordptr = g_malloc(record->length);
>> + /* make a copy of record to avoid being overwritten */
>> + memcpy(*recordptr, record, record->length);
So, I need to use a wrapper which should copy byte by byte taking care
of boundary overlaps, and that will also save us from crashing (as we
will never be crossing buffer boundaries), right ?
Harsh
>> + (*recordptr)->event&= ~TRACE_RECORD_VALID;
>> return true;
>> }
>
>>
>>>>>
>>>>> fflush(trace_fp);
>>>>> @@ -231,7 +196,7 @@ void st_set_trace_file_enabled(bool enable)
>>>>> static const TraceRecord header = {
>>>>> .event = HEADER_EVENT_ID,
>>>>> .timestamp_ns = HEADER_MAGIC,
>>>>> - .x1 = HEADER_VERSION,
>>>>> + .length = HEADER_VERSION,
>>>>
>>>>
>>>> Hmm...this is kind of ugly (see comment about using .length above) but
>>>> in this case most parsers will have a special-case anyway to check the
>>>> magic number. We need to use the .length field because historically
>>>> that's where the version is located.
>>>>
>>>
>>> So, lets keep the version here only, right ?
>>
>> Yes, it's necessary to do .length = HEADER_VERSION.
>>
>> Stefan
>>
>
>
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-18 10:52 ` Harsh Bora
@ 2012-01-18 10:59 ` Stefan Hajnoczi
2012-01-18 11:09 ` Harsh Bora
0 siblings, 1 reply; 23+ messages in thread
From: Stefan Hajnoczi @ 2012-01-18 10:59 UTC (permalink / raw)
To: Harsh Bora; +Cc: vilanova, qemu-devel, stefanha, aneesh.kumar
On Wed, Jan 18, 2012 at 10:52 AM, Harsh Bora <harsh@linux.vnet.ibm.com> wrote:
> On 01/18/2012 04:11 PM, Harsh Bora wrote:
>>
>> On 01/18/2012 04:01 PM, Stefan Hajnoczi wrote:
>>>
>>> On Wed, Jan 18, 2012 at 9:14 AM, Harsh Bora<harsh@linux.vnet.ibm.com>
>>> wrote:
>>>>
>>>> On 01/10/2012 10:11 PM, Stefan Hajnoczi wrote:
>>>>>>
>>>>>> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
>>>>>> writeout_idx += num_available;
>>>>>> }
>>>>>>
>>>>>> idx = writeout_idx % TRACE_BUF_LEN;
>>>>>> - while (get_trace_record(idx,&record)) {
>>>>>> - trace_buf[idx].event = 0; /* clear valid bit */
>>>>>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>>>>>> - idx = ++writeout_idx % TRACE_BUF_LEN;
>>>>>> + while (get_trace_record(idx,&recordptr)) {
>>>>>> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
>>>>>> + writeout_idx += recordptr->length;
>>>>>> + g_free(recordptr);
>>>>>> + recordptr = (TraceRecord *)&trace_buf[idx];
>>>>>>
>>>>>> + recordptr->event = 0;
>>>>>> + idx = writeout_idx % TRACE_BUF_LEN;
>>>>>> }
>>>>>
>>>>>
>>>>>
>>>>> I'm wondering if it's worth using a different approach here. Writing
>>>>> out individual records has bothered me.
>>>>>
>>>>> If we have a second buffer, as big as trace_buf[], then a function can
>>>>> copy out all records and make them available in trace_buf again:
>>>>>
>>>>> /**
>>>>> * Copy completed trace records out of the ring buffer
>>>>> *
>>>>> * @idx offset into trace_buf[]
>>>>> * @buf destination buffer
>>>>> * @len size of destination buffer
>>>>> * @ret the number of bytes consumed
>>>>> */
>>>>> size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
>>>>>
>>>>> That means consume gobbles up as many records as it can:
>>>>> * Until it reaches an invalid record which has not been written yet
>>>>> * Until it reaches the end of trace_buf[], the caller can call again
>>>>> with idx wrapped to 0
>>>>>
>>>>> After copying into buf[] it clears the valid bit in trace_buf[].
>>>>>
>>>>> Then the loop which calls consume_trace_records() does a single
>>>>> fwrite(3) and increments idx/writeout_idx.
>>>>>
>>>>> The advantage to this is that we write many records in one go and I
>>>>> think it splits up the writeout steps a little nicer than what we've
>>>>> previously done.
>>>>>
>>>>
>>>> I think this optimization can be introduced as a separate patch later.
>>>> Let me know if you think otherwise.
>>>
>>>
>>> Yes, that could be done later. However there is something incorrect
>>> here. Threads will continue to write trace records into the
>>> ringbuffer while the write-out thread is doing I/O. Think about what
>>> happens when threads overtake the write-out index modulo ringbuffer
>>> size. Since records are variable-length the write-out thread's next
>>> index could point into the middle of an overwritten record. And that
>>> means the ->length field is junk - we may crash if we use it.
>>
>>
>> In case of overwritten records, the valid bit of event id will also be
>> overwritten, and therefore we will not consider that record. Moreover,
>> the writeout thread will further get to know that some events were
>> dropped and will start with the latest trace_idx, right ?
>>
>> However, to handle the extreme rare case of having an overwritten value
>> such that its valid bit appears to be set, we can put a check for <
>> NR_TRACE_EVENTS. Even better to have a magic byte for events also ?
>>
>> Harsh
>
>
> Also, I just realized that we need to put buffer boundary checks while
> copying a trace record:
>
>
>>> -static bool get_trace_record(unsigned int idx, TraceRecord *record)
>>> +static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
>>> {
>>> - if (!(trace_buf[idx].event& TRACE_RECORD_VALID)) {
>>> + TraceRecord *record = (TraceRecord *)&trace_buf[idx];
>>> + if (!(record->event& TRACE_RECORD_VALID)) {
>>> return false;
>>> }
>>>
>>> __sync_synchronize(); /* read memory barrier before accessing record
>>> */
>>>
>>> - *record = trace_buf[idx];
>>> - record->event&= ~TRACE_RECORD_VALID;
>>> + *recordptr = g_malloc(record->length);
>>> + /* make a copy of record to avoid being overwritten */
>>> + memcpy(*recordptr, record, record->length);
>
> So, I need to use a wrapper which should copy byte by byte taking care of
> boundary overlaps, and that will also save us from crashing (as we will
> never be crossing buffer boundaries), right ?
It won't be enough if length has a junk value like 2^32 - 1. We don't
want to allocate/copy 4 GB :).
Stefan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record.
2012-01-18 10:59 ` Stefan Hajnoczi
@ 2012-01-18 11:09 ` Harsh Bora
0 siblings, 0 replies; 23+ messages in thread
From: Harsh Bora @ 2012-01-18 11:09 UTC (permalink / raw)
To: Stefan Hajnoczi; +Cc: aneesh.kumar, vilanova, stefanha, qemu-devel
On 01/18/2012 04:29 PM, Stefan Hajnoczi wrote:
> On Wed, Jan 18, 2012 at 10:52 AM, Harsh Bora<harsh@linux.vnet.ibm.com> wrote:
>> On 01/18/2012 04:11 PM, Harsh Bora wrote:
>>>
>>> On 01/18/2012 04:01 PM, Stefan Hajnoczi wrote:
>>>>
>>>> On Wed, Jan 18, 2012 at 9:14 AM, Harsh Bora<harsh@linux.vnet.ibm.com>
>>>> wrote:
>>>>>
>>>>> On 01/10/2012 10:11 PM, Stefan Hajnoczi wrote:
>>>>>>>
>>>>>>> + unused = fwrite(&record, ST_V2_REC_HDR_LEN, 1, trace_fp);
>>>>>>> writeout_idx += num_available;
>>>>>>> }
>>>>>>>
>>>>>>> idx = writeout_idx % TRACE_BUF_LEN;
>>>>>>> - while (get_trace_record(idx,&record)) {
>>>>>>> - trace_buf[idx].event = 0; /* clear valid bit */
>>>>>>> - unused = fwrite(&record, sizeof(record), 1, trace_fp);
>>>>>>> - idx = ++writeout_idx % TRACE_BUF_LEN;
>>>>>>> + while (get_trace_record(idx,&recordptr)) {
>>>>>>> + unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
>>>>>>> + writeout_idx += recordptr->length;
>>>>>>> + g_free(recordptr);
>>>>>>> + recordptr = (TraceRecord *)&trace_buf[idx];
>>>>>>>
>>>>>>> + recordptr->event = 0;
>>>>>>> + idx = writeout_idx % TRACE_BUF_LEN;
>>>>>>> }
>>>>>>
>>>>>>
>>>>>>
>>>>>> I'm wondering if it's worth using a different approach here. Writing
>>>>>> out individual records has bothered me.
>>>>>>
>>>>>> If we have a second buffer, as big as trace_buf[], then a function can
>>>>>> copy out all records and make them available in trace_buf again:
>>>>>>
>>>>>> /**
>>>>>> * Copy completed trace records out of the ring buffer
>>>>>> *
>>>>>> * @idx offset into trace_buf[]
>>>>>> * @buf destination buffer
>>>>>> * @len size of destination buffer
>>>>>> * @ret the number of bytes consumed
>>>>>> */
>>>>>> size_t consume_trace_records(unsigned int idx, void *buf, size_t len);
>>>>>>
>>>>>> That means consume gobbles up as many records as it can:
>>>>>> * Until it reaches an invalid record which has not been written yet
>>>>>> * Until it reaches the end of trace_buf[], the caller can call again
>>>>>> with idx wrapped to 0
>>>>>>
>>>>>> After copying into buf[] it clears the valid bit in trace_buf[].
>>>>>>
>>>>>> Then the loop which calls consume_trace_records() does a single
>>>>>> fwrite(3) and increments idx/writeout_idx.
>>>>>>
>>>>>> The advantage to this is that we write many records in one go and I
>>>>>> think it splits up the writeout steps a little nicer than what we've
>>>>>> previously done.
>>>>>>
>>>>>
>>>>> I think this optimization can be introduced as a separate patch later.
>>>>> Let me know if you think otherwise.
>>>>
>>>>
>>>> Yes, that could be done later. However there is something incorrect
>>>> here. Threads will continue to write trace records into the
>>>> ringbuffer while the write-out thread is doing I/O. Think about what
>>>> happens when threads overtake the write-out index modulo ringbuffer
>>>> size. Since records are variable-length the write-out thread's next
>>>> index could point into the middle of an overwritten record. And that
>>>> means the ->length field is junk - we may crash if we use it.
>>>
>>>
>>> In case of overwritten records, the valid bit of event id will also be
>>> overwritten, and therefore we will not consider that record. Moreover,
>>> the writeout thread will further get to know that some events were
>>> dropped and will start with the latest trace_idx, right ?
>>>
>>> However, to handle the extreme rare case of having an overwritten value
>>> such that its valid bit appears to be set, we can put a check for<
>>> NR_TRACE_EVENTS. Even better to have a magic byte for events also ?
>>>
>>> Harsh
>>
>>
>> Also, I just realized that we need to put buffer boundary checks while
>> copying a trace record:
>>
>>
>>>> -static bool get_trace_record(unsigned int idx, TraceRecord *record)
>>>> +static bool get_trace_record(unsigned int idx, TraceRecord **recordptr)
>>>> {
>>>> - if (!(trace_buf[idx].event& TRACE_RECORD_VALID)) {
>>>> + TraceRecord *record = (TraceRecord *)&trace_buf[idx];
>>>> + if (!(record->event& TRACE_RECORD_VALID)) {
>>>> return false;
>>>> }
>>>>
>>>> __sync_synchronize(); /* read memory barrier before accessing record
>>>> */
>>>>
>>>> - *record = trace_buf[idx];
>>>> - record->event&= ~TRACE_RECORD_VALID;
>>>> + *recordptr = g_malloc(record->length);
>>>> + /* make a copy of record to avoid being overwritten */
>>>> + memcpy(*recordptr, record, record->length);
>>
>> So, I need to use a wrapper which should copy byte by byte taking care of
>> boundary overlaps, and that will also save us from crashing (as we will
>> never be crossing buffer boundaries), right ?
>
> It won't be enough if length has a junk value like 2^32 - 1. We don't
> want to allocate/copy 4 GB :).
So, whats the max limit that we may want to propose for a record length
? Obviously less than buffer length, or TRACE_BUF_LEN / 2 ?
Hope, a check for max buffer length with byte-wise copy will help ?
Harsh
>
> Stefan
>
^ permalink raw reply [flat|nested] 23+ messages in thread
end of thread, other threads:[~2012-01-18 11:09 UTC | newest]
Thread overview: 23+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2012-01-10 10:59 [Qemu-devel] [RFC PATCH v3 0/3] simpletrace : support var num of args and strings Harsh Prateek Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 1/3] Converting tracetool.sh to tracetool.py Harsh Prateek Bora
2012-01-10 14:50 ` Stefan Hajnoczi
2012-01-11 6:25 ` Harsh Bora
2012-01-11 10:03 ` Stefan Hajnoczi
2012-01-10 21:45 ` Lluís Vilanova
2012-01-11 17:14 ` Stefan Hajnoczi
2012-01-10 22:51 ` Lluís Vilanova
2012-01-11 6:38 ` Harsh Bora
2012-01-11 8:46 ` Harsh Bora
2012-01-11 10:50 ` Stefan Hajnoczi
2012-01-12 9:33 ` Stefan Hajnoczi
2012-01-11 10:07 ` Stefan Hajnoczi
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 2/3] simpletrace-v2: Handle variable number/size of elements per trace record Harsh Prateek Bora
2012-01-10 16:41 ` Stefan Hajnoczi
2012-01-18 9:14 ` Harsh Bora
2012-01-18 10:31 ` Stefan Hajnoczi
2012-01-18 10:41 ` Harsh Bora
2012-01-18 10:52 ` Harsh Bora
2012-01-18 10:59 ` Stefan Hajnoczi
2012-01-18 11:09 ` Harsh Bora
2012-01-10 10:59 ` [Qemu-devel] [RFC PATCH v3 3/3] simpletrace.py: updated log reader script to handle new log format Harsh Prateek Bora
2012-01-11 12:30 ` Stefan Hajnoczi
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).