Systemtap with kernel markers?

[Theodore Tso]

So in attempt to help out Arjan van de Ven on a recent problem that he
posted on LKML, I patched ext4 with some markers (see attached patch).
The markers are definitely found in the in the kernel:

% nm /boot/vmlinux-2.6.27-rc7 | grep "__mark" | grep "\(ext4\)\|\(jbd2\)"
c0749b50 d __mark_ext4_sync_file.26899
c0749b70 d __mark_ext4_sync_fs.30089
c0749bd0 d __mark_jbd2_checkpoint.21365
c0749b90 d __mark_jbd2_end_commit.22202
c0749bb0 d __mark_jbd2_start_commit.22151

But when I try to use stap (the very latest bleeding edge), it doesn't work:

% stap -vvvvvvvvvv ext4-marker.stp
SystemTap translator/driver (version 0.7.1/0.131 git branch master, commit 06af1f31)
Copyright (C) 2005-2008 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
Session arch: i686 release: 2.6.27-rc7
Created temporary directory "/tmp/stapGA9lOa"
Searched '/usr/local/share/systemtap/tapset/i686/*.stp', found 2
Searched '/usr/local/share/systemtap/tapset/*.stp', found 43
Pass 1: parsed user script and 45 library script(s) in 320usr/20sys/340real ms.
'' '' ' '
semantic error: no match while resolving probe point kernel.mark("ext4_sync_file")
semantic error: no match while resolving probe point kernel.mark("ext4_sync_fs")
semantic error: no match while resolving probe point kernel.mark("jbd2_start_commit")
semantic error: no match while resolving probe point kernel.mark("jbd2_exit_commit")
semantic error: no match while resolving probe point kernel.mark("jbd2_checkpoint")
mark_builder releasing cache
semantic error: no probes found
Pass 2: analyzed script: 0 probe(s), 0 function(s), 0 embed(s), 0 global(s) in 10usr/0sys/5real ms.
Pass 2: analysis failed.  Try again with more '-v' (verbose) options.
Running rm -rf /tmp/stapGA9lOa

Any suggestions what I did wrong?

							- Ted


-------------- next part --------------
ext4: Add debugging markers that can be used by systemtap

This debugging markers are designed to debug problems such as the
random filesystem latency problems reported by Arjan.

Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
---
diff --git a/fs/ext4/fsync.c b/fs/ext4/fsync.c
index c37d1e8..f8b57a2 100644
--- a/fs/ext4/fsync.c
+++ b/fs/ext4/fsync.c
@@ -28,6 +28,7 @@
 #include <linux/writeback.h>
 #include <linux/jbd2.h>
 #include <linux/blkdev.h>
+#include <linux/marker.h>
 #include "ext4.h"
 #include "ext4_jbd2.h"
 
@@ -51,6 +52,10 @@ int ext4_sync_file(struct file *file, struct dentry *dentry, int datasync)
 
 	J_ASSERT(ext4_journal_current_handle() == NULL);
 
+	trace_mark(ext4_sync_file, "datasync %d dev %d ino %ld parent %ld",
+		   datasync, inode->i_sb->s_dev, inode->i_ino,
+		   dentry->d_parent->d_inode->i_ino);
+
 	/*
 	 * data=writeback:
 	 *  The caller's filemap_fdatawrite()/wait will sync the data.
diff --git a/fs/ext4/super.c b/fs/ext4/super.c
index 515af05..68b0301 100644
--- a/fs/ext4/super.c
+++ b/fs/ext4/super.c
@@ -35,6 +35,7 @@
 #include <linux/quotaops.h>
 #include <linux/seq_file.h>
 #include <linux/proc_fs.h>
+#include <linux/marker.h>
 #include <linux/log2.h>
 #include <linux/crc16.h>
 #include <asm/uaccess.h>
@@ -2950,6 +2951,7 @@ static int ext4_sync_fs(struct super_block *sb, int wait)
 {
 	tid_t target;
 
+	trace_mark(ext4_sync_fs, "dev %d wait %d", sb->s_dev, wait);
 	sb->s_dirt = 0;
 	if (jbd2_journal_start_commit(EXT4_SB(sb)->s_journal, &target)) {
 		if (wait)
diff --git a/fs/jbd2/checkpoint.c b/fs/jbd2/checkpoint.c
index 91389c8..72bec15 100644
--- a/fs/jbd2/checkpoint.c
+++ b/fs/jbd2/checkpoint.c
@@ -20,6 +20,7 @@
 #include <linux/time.h>
 #include <linux/fs.h>
 #include <linux/jbd2.h>
+#include <linux/marker.h>
 #include <linux/errno.h>
 #include <linux/slab.h>
 
@@ -313,6 +329,8 @@ int jbd2_log_do_checkpoint(journal_t *journal)
 	 * journal straight away.
 	 */
 	result = jbd2_cleanup_journal_tail(journal);
+	trace_mark(jbd2_checkpoint, "dev %d need_checkpoint %d",
+		   journal->j_fs_dev->bd_dev, result);
 	jbd_debug(1, "cleanup_journal_tail returned %d\n", result);
 	if (result <= 0)
 		return result;
diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index b091e53..ecb485b 100644
--- a/fs/jbd2/commit.c
+++ b/fs/jbd2/commit.c
@@ -16,6 +16,7 @@
 #include <linux/time.h>
 #include <linux/fs.h>
 #include <linux/jbd2.h>
+#include <linux/marker.h>
 #include <linux/errno.h>
 #include <linux/slab.h>
 #include <linux/mm.h>
@@ -368,6 +369,8 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	commit_transaction = journal->j_running_transaction;
 	J_ASSERT(commit_transaction->t_state == T_RUNNING);
 
+	trace_mark(jbd2_start_commit, "dev %d transaction %d",
+		   journal->j_fs_dev->bd_dev, commit_transaction->t_tid);
 	jbd_debug(1, "JBD: starting commit of transaction %d\n",
 			commit_transaction->t_tid);
 
@@ -985,6 +988,9 @@ restart_loop:
 	}
 	spin_unlock(&journal->j_list_lock);
 
+	trace_mark(jbd2_end_commit, "dev %d transaction %d head %d",
+		   journal->j_fs_dev->bd_dev, commit_transaction->t_tid,
+		   journal->j_tail_sequence);
 	jbd_debug(1, "JBD: commit %d complete, head %d\n",
 		  journal->j_commit_sequence, journal->j_tail_sequence);
 
-------------- next part --------------
probe kernel.mark("ext4_sync_file")
{
	printf("ext4_sync_file: datasync %d dev %d ino %d parent %d\n",
				$arg1, $arg2, $arg3, $arg4)
}

probe kernel.mark("ext4_sync_fs")
{
	printf("ext4_sync_fs: dev %d wait %d\n", $arg1, $arg2)
}

probe kernel.mark("jbd2_start_commit")
{
	printf("jbd2_start_commit: dev %d transaction %d\n", $arg1, $arg2)
}

probe kernel.mark("jbd2_exit_commit")
{
	printf("jbd2_exit_commit: dev %d transaction %d head %d\n",
	       $arg1, $arg2, $arg3)
}

probe kernel.mark("jbd2_checkpoint")
{
	printf("jbd2_checkpoint: dev %d need_checkpoint %d\n", $arg1,
      		  $arg2);
}