[RFC][PATCH] Add timestamp to process event connector message

[RFC][PATCH] Add timestamp to process event connector message

[Matt Helsley]

        This patch adds a timestamp field to the events sent via the process
event connector. The timestamp allows listeners to accurately account the
duration(s) between a process' events and offers strong means with which to
determine the order of events while also avoiding the addition of per-task data.

        This alters the size and layout of the event structure and hence would
break compatibility if process events connector as it stands in 2.6.15-rc5 were
released as a mainline kernel.

Signed-off-by: Matt Helsley <matthltc@us.ibm.com>

--

Index: linux-2.6.15-rc5/drivers/connector/cn_proc.c
===================================================================
--- linux-2.6.15-rc5.orig/drivers/connector/cn_proc.c
+++ linux-2.6.15-rc5/drivers/connector/cn_proc.c
@@ -42,10 +42,31 @@ static inline void get_seq(__u32 *ts, in
 	*ts = get_cpu_var(proc_event_counts)++;
 	*cpu = smp_processor_id();
 	put_cpu_var(proc_event_counts);
 }
 
+static inline void get_timestamp(struct timespec *ts)
+{
+	unsigned int seq;
+	struct timespec wall2mono;
+
+	/* synchronize with settimeofday() changes */
+	do {
+		seq = read_seqbegin(&xtime_lock);
+		getnstimeofday(ts);
+		wall2mono = wall_to_monotonic;
+	} while(read_seqretry(&xtime_lock, seq));
+
+	/* adjust to monotonicaly-increasing values */
+	ts += wall2mono.tv_sec;
+	ts += wall2mono.tv_nsec;
+	while ((ts->tv_nsec - NSEC_PER_SEC) >= 0) {
+		ts->tv_nsec -= NSEC_PER_SEC;
+		ts->tv_sec++;
+	}
+}
+
 void proc_fork_connector(struct task_struct *task)
 {
 	struct cn_msg *msg;
 	struct proc_event *ev;
 	__u8 buffer[CN_PROC_MSG_SIZE];
@@ -54,10 +75,11 @@ void proc_fork_connector(struct task_str
 		return;
 
 	msg = (struct cn_msg*)buffer;
 	ev = (struct proc_event*)msg->data;
 	get_seq(&msg->seq, &ev->cpu);
+	get_timestamp(&ev->timestamp);
 	ev->what = PROC_EVENT_FORK;
 	ev->event_data.fork.parent_pid = task->real_parent->pid;
 	ev->event_data.fork.parent_tgid = task->real_parent->tgid;
 	ev->event_data.fork.child_pid = task->pid;
 	ev->event_data.fork.child_tgid = task->tgid;
@@ -79,10 +101,11 @@ void proc_exec_connector(struct task_str
 		return;
 
 	msg = (struct cn_msg*)buffer;
 	ev = (struct proc_event*)msg->data;
 	get_seq(&msg->seq, &ev->cpu);
+	get_timestamp(&ev->timestamp);
 	ev->what = PROC_EVENT_EXEC;
 	ev->event_data.exec.process_pid = task->pid;
 	ev->event_data.exec.process_tgid = task->tgid;
 
 	memcpy(&msg->id, &cn_proc_event_id, sizeof(msg->id));
@@ -112,10 +135,11 @@ void proc_id_connector(struct task_struc
 	   	ev->event_data.id.r.rgid = task->gid;
 	   	ev->event_data.id.e.egid = task->egid;
 	} else
 	     	return;
 	get_seq(&msg->seq, &ev->cpu);
+	get_timestamp(&ev->timestamp);
 
 	memcpy(&msg->id, &cn_proc_event_id, sizeof(msg->id));
 	msg->ack = 0; /* not used */
 	msg->len = sizeof(*ev);
 	cn_netlink_send(msg, CN_IDX_PROC, GFP_KERNEL);
@@ -131,10 +155,11 @@ void proc_exit_connector(struct task_str
 		return;
 
 	msg = (struct cn_msg*)buffer;
 	ev = (struct proc_event*)msg->data;
 	get_seq(&msg->seq, &ev->cpu);
+	get_timestamp(&ev->timestamp);
 	ev->what = PROC_EVENT_EXIT;
 	ev->event_data.exit.process_pid = task->pid;
 	ev->event_data.exit.process_tgid = task->tgid;
 	ev->event_data.exit.exit_code = task->exit_code;
 	ev->event_data.exit.exit_signal = task->exit_signal;
@@ -163,10 +188,11 @@ static void cn_proc_ack(int err, int rcv
 		return;
 
 	msg = (struct cn_msg*)buffer;
 	ev = (struct proc_event*)msg->data;
 	msg->seq = rcvd_seq;
+	get_timestamp(&ev->timestamp);
 	ev->cpu = -1;
 	ev->what = PROC_EVENT_NONE;
 	ev->event_data.ack.err = err;
 	memcpy(&msg->id, &cn_proc_event_id, sizeof(msg->id));
 	msg->ack = rcvd_ack + 1;
Index: linux-2.6.15-rc5/include/linux/cn_proc.h
===================================================================
--- linux-2.6.15-rc5.orig/include/linux/cn_proc.h
+++ linux-2.6.15-rc5/include/linux/cn_proc.h
@@ -24,10 +24,11 @@
 
 #ifndef CN_PROC_H
 #define CN_PROC_H
 
 #include <linux/types.h>
+#include <linux/time.h>
 #include <linux/connector.h>
 
 /*
  * Userspace sends this enum to register with the kernel that it is listening
  * for events on the connector.
@@ -63,10 +64,11 @@ struct proc_event {
 		/* "next" should be 0x00000400 */
 		/* "last" is the last process event: exit */
 		PROC_EVENT_EXIT = 0x80000000
 	} what;
 	__u32 cpu;
+	struct timespec timestamp;
 	union { /* must be last field of proc_event struct */
 		struct {
 			__u32 err;
 		} ack;
 

Re: [ckrm-tech] [RFC][PATCH] Add timestamp to process event connector message

[Dave Hansen]

On Mon, 2005-12-05 at 18:21 -0800, Matt Helsley wrote:
> +static inline void get_timestamp(struct timespec *ts)
> +{
> +       unsigned int seq;
> +       struct timespec wall2mono;
> +
> +       /* synchronize with settimeofday() changes */
> +       do {
> +               seq = read_seqbegin(&xtime_lock);
> +               getnstimeofday(ts);
> +               wall2mono = wall_to_monotonic;
> +       } while(read_seqretry(&xtime_lock, seq));
> +
> +       /* adjust to monotonicaly-increasing values */
> +       ts += wall2mono.tv_sec;
> +       ts += wall2mono.tv_nsec;
> +       while ((ts->tv_nsec - NSEC_PER_SEC) >= 0) {
> +               ts->tv_nsec -= NSEC_PER_SEC;
> +               ts->tv_sec++;
> +       }
> +}

This seems like something a bit too generic to have in your
drivers/connector/cn_proc.c file.  Is there a generic timekeeping
function that should be used instead?  Or, should this go into one of
the timekeeping files?

-- Dave

Re: [ckrm-tech] [RFC][PATCH] Add timestamp to process event connector message

[Matt Helsley]

On Mon, 2005-12-05 at 18:39 -0800, Dave Hansen wrote: 
> On Mon, 2005-12-05 at 18:21 -0800, Matt Helsley wrote:
> > +static inline void get_timestamp(struct timespec *ts)
> > +{
> > +       unsigned int seq;
> > +       struct timespec wall2mono;
> > +
> > +       /* synchronize with settimeofday() changes */
> > +       do {
> > +               seq = read_seqbegin(&xtime_lock);
> > +               getnstimeofday(ts);
> > +               wall2mono = wall_to_monotonic;
> > +       } while(read_seqretry(&xtime_lock, seq));
> > +
> > +       /* adjust to monotonicaly-increasing values */
> > +       ts += wall2mono.tv_sec;
> > +       ts += wall2mono.tv_nsec;
> > +       while ((ts->tv_nsec - NSEC_PER_SEC) >= 0) {
> > +               ts->tv_nsec -= NSEC_PER_SEC;
> > +               ts->tv_sec++;
> > +       }
> > +}
> 
> This seems like something a bit too generic to have in your
> drivers/connector/cn_proc.c file.  Is there a generic timekeeping
> function that should be used instead?  Or, should this go into one of
> the timekeeping files?
> 
> -- Dave

An excellent point! 

There are two functions that might seem appropriate for a timestamp:

current_kernel_time()
do_gettimeofday()


	The former has jiffies resolution and hence may not be sufficient to
distinguish ordering between two events in the same process. The second
is interpolated wall time and may not necessarily monotonic. 

	Most other methods, such as get_cycles(), reading the tsc, etc. are not
SMP-safe or do not provide the needed resolution. Hence the patch gets
the time in nanoseconds and converts to a monotonicly increasing value.

	I'll split out a similarly-named function (get_timestamp exists in
ibmasm.c) to kernel/time.c and repost as two patches.

Thanks,
	-Matt Helsley