Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 9eed1842 authored by Steven Cahail's avatar Steven Cahail
Browse files

trace: ipc_logging: Add QTimer timestamp alongside kernel timestamp 



IPC Logging currently displays the kernel log timestamp, which is based on
a timer that does not increase when the Apps processor is in suspend. This
means that the kernel log timestamp "loses time" and cannot be correlated
with events on other processors. The source of the QTimer timestamp is
always running and has the same source as other logs in the system, which
makes it convenient to correlate logs across the system.

In IPC Logging, display the QTimer timestamp next to the kernel timestamp
to make it easier to correlate logs across the system. Increase the IPC
Logging version to 2 to enable compatibility with tools that extract the
logs from memory dumps.

Change-Id: I9cdb3dbfc2a7edd99ca6f8d91d7c09854ba37395
Signed-off-by: default avatarSteven Cahail <scahail@codeaurora.org>
parent 4a0b6988

include/linux/ipc_logging.h

+24 −1
Original line number Diff line number Diff line 
/* Copyright (c) 2012-2014, The Linux Foundation. All rights reserved.

/* Copyright (c) 2012-2015, The Linux Foundation. All rights reserved.

 *

 * This program is free software; you can redistribute it and/or modify

 * it under the terms of the GNU General Public License version 2 and
@@ -70,6 +70,13 @@ void msg_encode_start(struct encode_context *ectxt, uint32_t type); 
 */

int tsv_timestamp_write(struct encode_context *ectxt);



/*

 * tsv_qtimer_write: Writes the current QTimer timestamp count

 *

 * @ectxt: Context initialized by calling msg_encode_start()

 */

int tsv_qtimer_write(struct encode_context *ectxt);



/*

 * tsv_pointer_write: Writes a data pointer

 *
@@ -154,6 +161,16 @@ do { \ 
void tsv_timestamp_read(struct encode_context *ectxt,

			struct decode_context *dctxt, const char *format);



/*

 * tsv_qtimer_read: Reads a QTimer timestamp

 *

 * @ectxt:  Context retrieved by reading from log space

 * @dctxt:  Temporary storage to hold the decoded message

 * @format: Output format while dumping through DEBUGFS

 */

void tsv_qtimer_read(struct encode_context *ectxt,

		     struct decode_context *dctxt, const char *format);



/*

 * tsv_pointer_read: Reads a data pointer

 *
@@ -219,6 +236,9 @@ static inline void msg_encode_start(struct encode_context *ectxt, 
static inline int tsv_timestamp_write(struct encode_context *ectxt)

{ return -EINVAL; }



static inline int tsv_qtimer_write(struct encode_context *ectxt)

{ return -EINVAL; }



static inline int tsv_pointer_write(struct encode_context *ectxt, void *pointer)

{ return -EINVAL; }
@@ -244,6 +264,9 @@ static inline int ipc_log_extract(void *ilctxt, char *buff, int size) 
static inline void tsv_timestamp_read(struct encode_context *ectxt,

			struct decode_context *dctxt, const char *format) { }



static inline void tsv_qtimer_read(struct encode_context *ectxt,

			struct decode_context *dctxt, const char *format) { }



static inline void tsv_pointer_read(struct encode_context *ectxt,

		      struct decode_context *dctxt, const char *format) { }

kernel/trace/ipc_logging.c

+47 −3
Original line number Diff line number Diff line 
/* Copyright (c) 2012-2014, The Linux Foundation. All rights reserved.

/* Copyright (c) 2012-2015, The Linux Foundation. All rights reserved.

 *

 * This program is free software; you can redistribute it and/or modify

 * it under the terms of the GNU General Public License version 2 and
@@ -11,6 +11,7 @@ 
 *

 */



#include <asm/arch_timer.h>

#include <linux/slab.h>

#include <linux/uaccess.h>

#include <linux/module.h>
@@ -419,6 +420,23 @@ int tsv_timestamp_write(struct encode_context *ectxt) 
}

EXPORT_SYMBOL(tsv_timestamp_write);



/*

 * Writes the current QTimer timestamp count.

 *

 * @ectxt   context initialized by calling msg_encode_start()

 */

int tsv_qtimer_write(struct encode_context *ectxt)

{

	int ret;

	uint64_t t_now = arch_counter_get_cntpct();



	ret = tsv_write_header(ectxt, TSV_TYPE_QTIMER, sizeof(t_now));

	if (ret)

		return ret;

	return tsv_write_data(ectxt, &t_now, sizeof(t_now));

}

EXPORT_SYMBOL(tsv_qtimer_write);



/*

 * Writes a data pointer.

 *
@@ -486,6 +504,7 @@ int ipc_log_string(void *ilctxt, const char *fmt, ...) 


	msg_encode_start(&ectxt, TSV_TYPE_STRING);

	tsv_timestamp_write(&ectxt);

	tsv_qtimer_write(&ectxt);

	avail_size = (MAX_MSG_SIZE - (ectxt.offset + hdr_size));

	va_start(arg_list, fmt);

	data_size = vsnprintf((ectxt.buff + ectxt.offset + hdr_size),
@@ -586,7 +605,7 @@ static void tsv_read_header(struct encode_context *ectxt, 
 *

 * @ectxt   context initialized by calling msg_read()

 * @dctxt   deserialization context

 * @format output format (appended to %6u.%09u timestamp format)

 * @format output format (appended to %6u.09u timestamp format)

 */

void tsv_timestamp_read(struct encode_context *ectxt,

			struct decode_context *dctxt, const char *format)
@@ -599,11 +618,36 @@ void tsv_timestamp_read(struct encode_context *ectxt, 
	BUG_ON(hdr.type != TSV_TYPE_TIMESTAMP);

	tsv_read_data(ectxt, &val, sizeof(val));

	nanosec_rem = do_div(val, 1000000000U);

	IPC_SPRINTF_DECODE(dctxt, "[%6u.%09lu]%s",

	IPC_SPRINTF_DECODE(dctxt, "[%6u.%09lu%s/",

			(unsigned)val, nanosec_rem, format);

}

EXPORT_SYMBOL(tsv_timestamp_read);



/*

 * Reads a QTimer timestamp.

 *

 * @ectxt   context initialized by calling msg_read()

 * @dctxt   deserialization context

 * @format output format (appended to %#18llx timestamp format)

 */

void tsv_qtimer_read(struct encode_context *ectxt,

		     struct decode_context *dctxt, const char *format)

{

	struct tsv_header hdr;

	uint64_t val;



	tsv_read_header(ectxt, &hdr);

	BUG_ON(hdr.type != TSV_TYPE_QTIMER);

	tsv_read_data(ectxt, &val, sizeof(val));



	/*

	 * This gives 16 hex digits of output. The # prefix prepends

	 * a 0x, and these characters count as part of the number.

	 */

	IPC_SPRINTF_DECODE(dctxt, "%#18llx]%s", val, format);

}

EXPORT_SYMBOL(tsv_qtimer_read);



/*

 * Reads a data pointer.

 *

kernel/trace/ipc_logging_debug.c

+2 −1
Original line number Diff line number Diff line
@@ -134,6 +134,7 @@ static void dfunc_string(struct encode_context *ectxt, 
			 struct decode_context *dctxt)

{

	tsv_timestamp_read(ectxt, dctxt, "");

	tsv_qtimer_read(ectxt, dctxt, " ");

	tsv_byte_array_read(ectxt, dctxt, "");



	/* add trailing \n if necessary */

kernel/trace/ipc_logging_private.h

+3 −2
Original line number Diff line number Diff line 
/* Copyright (c) 2012-2014, The Linux Foundation. All rights reserved.

/* Copyright (c) 2012-2015, The Linux Foundation. All rights reserved.

 *

 * This program is free software; you can redistribute it and/or modify

 * it under the terms of the GNU General Public License version 2 and
@@ -15,7 +15,7 @@ 


#include <linux/ipc_logging.h>



#define IPC_LOG_VERSION 0x0001

#define IPC_LOG_VERSION 0x0002

#define IPC_LOG_MAX_CONTEXT_NAME_LEN 20



/**
@@ -133,6 +133,7 @@ enum { 
	TSV_TYPE_POINTER,

	TSV_TYPE_INT32,

	TSV_TYPE_BYTE_ARRAY,

	TSV_TYPE_QTIMER,

};



enum {