trace buffer tapset proposal

trace buffer tapset proposal

[William Cohen]

[-- Attachment #1: Type: text/plain, Size: 6285 bytes --]

I have been looking over uses of systemtap. The flight recorder mode is useful for avoiding generating output. However, it may still generate a huge amount of output; basically output everything in the buffer. People might want want more focused output of data when a particular event occurs. Today I spent some time implementing a "trace buffer" tapset. Any comments about the implementation and use would be appreciated. The tapset has the following functions:

/**
 * sfunction trace_buffer_time - Default time of day for trace buffer
 */

/**
 * sfunction trace_buffer_create - Create a trace buffer
 * @name: Name of trace buffer
 * @size: Number of elements in trace buffer
 */

/**
 * sfunction trace_buffer_entry - Add an entry to a trace buffer
 * @name: Name of trace buffer
 * @line: Data to store in buffer
 */

/**
 * sfunction trace_buffer_print - Print out a trace buffer
 * @name: Name of trace buffer
 */

The tapset allows multiple trace_buffers to be used in the same script by giving each trace buffer a unique name.  The trace_buffer_time function is in a separate file, so the user can replace it is a different time base if desired.

Below is the sample set up to show output when a drive is unmounted.


 ../systemtap_write/install/bin/stap scsi_trace_buffer.stp 'kernel.function("deactivate_super")'
Back trace of events
[    27431318] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2c 40 00 00 80 00 00
[    27434132] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2c c0 00 00 80 00 00
[    27437933] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2d 40 00 00 80 00 00
[    27440776] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2d c0 00 00 80 00 00
[    27444553] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2e 40 00 00 80 00 00
[    27447354] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2e c0 00 00 80 00 00
[    27450406] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2f 40 00 00 80 00 00
[    27453218] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 2f c0 00 00 80 00 00
[    27456482] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 30 40 00 00 80 00 00
[    27459370] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 30 c0 00 00 80 00 00
[    27462456] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 31 40 00 00 80 00 00
[    27465231] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 31 c0 00 00 80 00 00
[    27468569] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 32 40 00 00 80 00 00
[    27471363] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 32 c0 00 00 80 00 00
[    27474555] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 33 40 00 00 80 00 00
[    27477359] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 33 c0 00 00 80 00 00
[    27480429] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 34 40 00 00 80 00 00
[    27483264] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 34 c0 00 00 80 00 00
[    27486996] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 35 40 00 00 80 00 00
[    27489891] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 35 c0 00 00 80 00 00
[    27493048] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 36 40 00 00 80 00 00
[    27495851] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 36 c0 00 00 80 00 00
[    27498931] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 37 40 00 00 80 00 00
[    27501729] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 37 c0 00 00 80 00 00
[    27505418] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 38 40 00 00 80 00 00
[    27508265] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 38 c0 00 00 80 00 00
[    27512039] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 39 40 00 00 80 00 00
[    27515044] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 39 c0 00 00 80 00 00
[    27518154] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 3a 40 00 00 80 00 00
[    27521121] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 3a c0 00 00 80 00 00
[    27524300] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 3b 40 00 00 80 00 00
[    27527102] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 3b c0 00 00 80 00 00
[    27530236] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 00 00 3c 40 00 00 80 00 00
[    28611412] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 06 55 31 d8 00 03 b0 00 00
[    28639875] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x06
 00 00 00 00 00 00 00
[    28640331] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x06
 00 00 00 00 00 00 00
[    30312985] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 02 13 c6 60 00 00 08 00 00
[    30312922] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 02 8b db 50 00 00 08 00 00
[    30314209] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 03 16 f3 08 00 00 e8 00 00
[    30314840] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 35 00 00 00 00 00 00 00 00 00 00
[    30353826] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 03 16 f3 f0 00 00 08 00 00
[    30353953] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 35 00 00 00 00 00 00 00 00 00 00
[    30639795] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x06
 00 00 00 00 00 00 00
[    30640372] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x06
 00 00 00 00 00 00 00
[    31133096] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 28 00 06 24 3d d8 00 00 88 00 00
[    31499572] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 01 95 d2 c0 00 00 f0 00 00
[    31499617] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 01 b7 1e 78 00 04 00 00 00
[    31499646] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x0a
 2a 00 01 b7 22 78 00 00 f0 00 00
[    32639934] SCSI  chan=0x00, target=0x00, lun=0x00, cmd_len=0x06
 00 00 00 00 00 00 00


[-- Attachment #2: trace_buffer.stp --]
[-- Type: text/plain, Size: 1810 bytes --]

// trace_buffer tapset
// Copyright (c) 2010 Red Hat Inc.
//
// This file is part of systemtap, and is free software.  You can
// redistribute it and/or modify it under the terms of the GNU General
// Public License (GPL); either version 2, or (at your option) any
// later version.

global trace_buffer_ts, trace_buffer_entry, trace_buffer_histidx
global trace_buffer_N, trace_buffer_start_time

#trace_buffer_time is in a separate file so user can change it if needed

/**
 * sfunction trace_buffer_create - Create a trace buffer
 * @name: Name of trace buffer
 * @size: Number of elements in trace buffer
 */
function trace_buffer_create(name:string, size:long)
{
	if (size <= 0)
		error("Incorrectly sized trace buffer (<=0)")
	trace_buffer_N[name] = size
	trace_buffer_start_time[name] = trace_buffer_time()
	trace_buffer_histidx[name] = 0
}

/**
 * sfunction trace_buffer_entry - Add an entry to a trace buffer
 * @name: Name of trace buffer
 * @line: Data to store in buffer
 */
function trace_buffer_entry(name:string, line:string)
{
	t = trace_buffer_time()
	N = trace_buffer_N[name]
	if (!N)
		error("No trace buffer named " . name)
	# move to the next element
	histidx = (trace_buffer_histidx[name] + 1) % N
	trace_buffer_histidx[name] = histidx
	trace_buffer_entry[name, histidx] = line
	trace_buffer_ts[name, histidx] = t
}

/**
 * sfunction trace_buffer_print - Print out a trace buffer
 * @name: Name of trace buffer
 */
function trace_buffer_print(name:string)
{
	start_time = trace_buffer_start_time[name]
	N = trace_buffer_N[name]
	start = (trace_buffer_histidx[name] + 1) % N
	stop = trace_buffer_histidx[name]
	for (i = start; i != stop; i = (i + 1) % N)
		if (trace_buffer_ts[name,i])
	    		printf("[%12d] %s\n",
				trace_buffer_ts[name,i]-start_time,
				trace_buffer_entry[name,i])
}


[-- Attachment #3: trace_buffer_time.stp --]
[-- Type: text/plain, Size: 138 bytes --]

/**
 * sfunction trace_buffer_time - Default time of day for trace buffer
 */
function trace_buffer_time () { return gettimeofday_us() }


[-- Attachment #4: scsi_trace_buffer.stp --]
[-- Type: text/plain, Size: 1978 bytes --]

#! /usr/bin/env stap
# Example showing the use the the trace buffer tapset
# record informaiton in trace buffer until trigger prints things out

# Information about scsi operation gleaned from:
# http://www.oreillynet.com/pub/a/oreilly/linux/news/cox_0999.html

probe begin { trace_buffer_create("scsi", 50) }

# probe to capture scsi commands
probe kernel.function("scsi_dispatch_cmd")
{
  # format the command and put in commands array
  if ($cmd) {
  s = s . sprintf("SCSI  chan=0x%02x, target=0x%02x, lun=0x%02x, cmd_len=0x%02x\n",
      $cmd->device->channel, $cmd->device->id, $cmd->device->lun,
      $cmd->cmd_len);
  cmd_len = $cmd->cmd_len
  if (cmd_len >= 0) s = s . sprintf (" %02x", $cmd->cmnd[0]);
  if (cmd_len >= 1) s = s . sprintf (" %02x", $cmd->cmnd[1]);
  if (cmd_len >= 2) s = s . sprintf (" %02x", $cmd->cmnd[2]);
  if (cmd_len >= 3) s = s . sprintf (" %02x", $cmd->cmnd[3]);
  if (cmd_len >= 4) s = s . sprintf (" %02x", $cmd->cmnd[4]);
  if (cmd_len >= 5) s = s . sprintf (" %02x", $cmd->cmnd[5]);
  if (cmd_len >= 6) s = s . sprintf (" %02x", $cmd->cmnd[6]);
  if (cmd_len >= 7) s = s . sprintf (" %02x", $cmd->cmnd[7]);
  if (cmd_len >= 8) s = s . sprintf (" %02x", $cmd->cmnd[8]);
  if (cmd_len >= 9) s = s . sprintf (" %02x", $cmd->cmnd[9]);
  if (cmd_len >= 10) s = s . sprintf (" %02x", $cmd->cmnd[10]);
  if (cmd_len >= 11) s = s . sprintf (" %02x", $cmd->cmnd[11]);
  if (cmd_len >= 12) s = s . sprintf (" %02x", $cmd->cmnd[12]);
  if (cmd_len >= 13) s = s . sprintf (" %02x", $cmd->cmnd[13]);
  if (cmd_len >= 14) s = s . sprintf (" %02x", $cmd->cmnd[14]);
  if (cmd_len >= 15) s = s . sprintf (" %02x", $cmd->cmnd[15]);
  if (cmd_len >= 16) s = s . " cmd_len >= 16"
  }
  trace_buffer_entry("scsi", s)
}

# probe to trigger printing flight recorder information
# default print information when exiting
# optionally specify probe event
probe
%( $# >= 1 %? $1 %: end %)
{
  print("Back trace of events\n")
  trace_buffer_print("scsi")
  exit()
}

Re: trace buffer tapset proposal

[Frank Ch. Eigler]

William Cohen <wcohen@redhat.com> writes:

> [...] I spent some time implementing a "trace buffer" tapset. [...]

Perhaps this sort of thing would be better as a testsuite.example than
a tapset, at least until its utility is more clear.  (Note that the
tutorial includes an exercise to construct something simlar to this.
Hm, I wonder if we should provide sample solutions to the exercises!)

By the way, in the example usage, this:
 
  if (cmd_len >= 0) s = s . sprintf (" %02x", $cmd->cmnd[0]);
  if (cmd_len >= 1) s = s . sprintf (" %02x", $cmd->cmnd[1]);
  [...]
  if (cmd_len >= 14) s = s . sprintf (" %02x", $cmd->cmnd[14]);
  if (cmd_len >= 15) s = s . sprintf (" %02x", $cmd->cmnd[15]);

might be approximately abbreviated as:

  s = sprintf("%*M", cmd_len, $cmd->cmnd)

- FChE