[PATCH v2 0/3] Add events to trace remoteproc lifecycle

[PATCH v2 0/3] Add events to trace remoteproc lifecycle

[Rishabh Bhatnagar]

Insert tracepoints in mdt_loader, qcom_scm and remoteproc_core drivers.
These tracepoints will be used to analyze the time taken
at each step during bootup/shutdown of the remoteproc. Tracepoints
in mdt_loader driver provides information about location and size
of firmware segments being loaded. Also trace the scm pas calls
used to boot/load remote processors.

Changelog:

v2 -> v1:
- Add traces in qcom_scm driver
- Add traces in remoteproc core to trace the remoteproc state
- Trace the physical address where segment is loaded in mdt_loader

Rishabh Bhatnagar (3):
  soc: qcom: Add tracepoints to mdt loader
  firmware: scm: Add tracepoints to scm driver for pas calls
  remoteproc: Add ftrace events to trace lifecycle of remoteprocs

 drivers/firmware/qcom_scm.c          |  9 ++++
 drivers/remoteproc/remoteproc_core.c | 19 +++++++-
 drivers/soc/qcom/mdt_loader.c        |  7 +++
 include/trace/events/mdt_loader.h    | 38 +++++++++++++++
 include/trace/events/qcom_scm.h      | 34 ++++++++++++++
 include/trace/events/remoteproc.h    | 91 ++++++++++++++++++++++++++++++++++++
 6 files changed, 197 insertions(+), 1 deletion(-)
 create mode 100644 include/trace/events/mdt_loader.h
 create mode 100644 include/trace/events/qcom_scm.h
 create mode 100644 include/trace/events/remoteproc.h

-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

[PATCH v2 1/3] soc: qcom: Add tracepoints to mdt loader

[Rishabh Bhatnagar]

Add trace events to the mdt loader driver. These events
can help us trace the region where we are loading the
segments and the time it takes to initialize the image
and setup the memory region.

Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
---
 drivers/soc/qcom/mdt_loader.c     |  7 +++++++
 include/trace/events/mdt_loader.h | 38 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 45 insertions(+)
 create mode 100644 include/trace/events/mdt_loader.h

diff --git a/drivers/soc/qcom/mdt_loader.c b/drivers/soc/qcom/mdt_loader.c
index 24cd193..96dc912 100644
--- a/drivers/soc/qcom/mdt_loader.c
+++ b/drivers/soc/qcom/mdt_loader.c
@@ -17,6 +17,9 @@
 #include <linux/slab.h>
 #include <linux/soc/qcom/mdt_loader.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/mdt_loader.h>
+
 static bool mdt_phdr_valid(const struct elf32_phdr *phdr)
 {
 	if (phdr->p_type != PT_LOAD)
@@ -198,6 +201,7 @@ static int __qcom_mdt_load(struct device *dev, const struct firmware *fw,
 		if (pas_init) {
 			ret = qcom_scm_pas_mem_setup(pas_id, mem_phys,
 						     max_addr - min_addr);
+
 			if (ret) {
 				dev_err(dev, "unable to setup relocation\n");
 				goto out;
@@ -232,6 +236,7 @@ static int __qcom_mdt_load(struct device *dev, const struct firmware *fw,
 
 		ptr = mem_region + offset;
 
+
 		if (phdr->p_filesz && phdr->p_offset < fw->size) {
 			/* Firmware is large enough to be non-split */
 			if (phdr->p_offset + phdr->p_filesz > fw->size) {
@@ -256,6 +261,8 @@ static int __qcom_mdt_load(struct device *dev, const struct firmware *fw,
 			release_firmware(seg_fw);
 		}
 
+		trace_qcom_mdt_load_segment(mem_phys + offset, phdr->p_filesz,
+					    fw_name);
 		if (phdr->p_memsz > phdr->p_filesz)
 			memset(ptr + phdr->p_filesz, 0, phdr->p_memsz - phdr->p_filesz);
 	}
diff --git a/include/trace/events/mdt_loader.h b/include/trace/events/mdt_loader.h
new file mode 100644
index 0000000..01c2461
--- /dev/null
+++ b/include/trace/events/mdt_loader.h
@@ -0,0 +1,38 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2020, The Linux Foundation. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM mdt_loader
+
+#if !defined(_TRACE_MDT_LOADER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_MDT_LOADER_H
+
+#include <linux/types.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(qcom_mdt_load_segment,
+
+	TP_PROTO(phys_addr_t region_start, size_t region_size, const char *fw),
+
+	TP_ARGS(region_start, region_size, fw),
+
+	TP_STRUCT__entry(
+		__field(phys_addr_t, region_start)
+		__field(size_t, region_size)
+		__string(fw, fw)
+	),
+
+	TP_fast_assign(
+		__entry->region_start = region_start;
+		__entry->region_size = region_size;
+		__assign_str(fw, fw);
+	),
+
+	TP_printk("firmware:%s region start=%pa size=%zx",
+		  __get_str(fw), __entry->region_start, __entry->region_size)
+);
+
+#endif
+#include <trace/define_trace.h>
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH v2 1/3] soc: qcom: Add tracepoints to mdt loader

[kernel test robot]

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

Hi Rishabh,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on tip/perf/core]
[also build test WARNING on linux/master linus/master v5.10-rc4 next-20201116]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]

url:    https://github.com/0day-ci/linux/commits/Rishabh-Bhatnagar/Add-events-to-trace-remoteproc-lifecycle/20201117-054729
base:   https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git 306e3e91edf1c6739a55312edd110d298ff498dd
config: arm-allmodconfig (attached as .config)
compiler: arm-linux-gnueabi-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/0day-ci/linux/commit/437cc5c0ceb1f4b36564b99d7289af089576fdd0
        git remote add linux-review https://github.com/0day-ci/linux
        git fetch --no-tags linux-review Rishabh-Bhatnagar/Add-events-to-trace-remoteproc-lifecycle/20201117-054729
        git checkout 437cc5c0ceb1f4b36564b99d7289af089576fdd0
        # save the attached .config to linux build tree
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=arm 

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@intel.com>

All warnings (new ones prefixed by >>):

   In file included from include/trace/define_trace.h:102,
                    from include/trace/events/mdt_loader.h:38,
                    from drivers/soc/qcom/mdt_loader.c:21:
   include/trace/events/mdt_loader.h: In function 'trace_raw_output_qcom_mdt_load_segment':
>> include/trace/events/mdt_loader.h:33:12: warning: format '%p' expects argument of type 'void *', but argument 4 has type 'phys_addr_t' {aka 'unsigned int'} [-Wformat=]
      33 |  TP_printk("firmware:%s region start=%pa size=%zx",
         |            ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
   include/trace/trace_events.h:367:22: note: in definition of macro 'DECLARE_EVENT_CLASS'
     367 |  trace_seq_printf(s, print);     \
         |                      ^~~~~
   include/trace/trace_events.h:80:9: note: in expansion of macro 'PARAMS'
      80 |         PARAMS(print));         \
         |         ^~~~~~
   include/trace/events/mdt_loader.h:15:1: note: in expansion of macro 'TRACE_EVENT'
      15 | TRACE_EVENT(qcom_mdt_load_segment,
         | ^~~~~~~~~~~
   include/trace/events/mdt_loader.h:33:2: note: in expansion of macro 'TP_printk'
      33 |  TP_printk("firmware:%s region start=%pa size=%zx",
         |  ^~~~~~~~~
   In file included from include/trace/trace_events.h:401,
                    from include/trace/define_trace.h:102,
                    from include/trace/events/mdt_loader.h:38,
                    from drivers/soc/qcom/mdt_loader.c:21:
   include/trace/events/mdt_loader.h:33:39: note: format string is defined here
      33 |  TP_printk("firmware:%s region start=%pa size=%zx",
         |                                      ~^
         |                                       |
         |                                       void *
         |                                      %d

vim +33 include/trace/events/mdt_loader.h

    16	
    17		TP_PROTO(phys_addr_t region_start, size_t region_size, const char *fw),
    18	
    19		TP_ARGS(region_start, region_size, fw),
    20	
    21		TP_STRUCT__entry(
    22			__field(phys_addr_t, region_start)
    23			__field(size_t, region_size)
    24			__string(fw, fw)
    25		),
    26	
    27		TP_fast_assign(
    28			__entry->region_start = region_start;
    29			__entry->region_size = region_size;
    30			__assign_str(fw, fw);
    31		),
    32	
  > 33		TP_printk("firmware:%s region start=%pa size=%zx",
    34			  __get_str(fw), __entry->region_start, __entry->region_size)
    35	);
    36	

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@lists.01.org

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 76510 bytes --]

Re: [PATCH v2 1/3] soc: qcom: Add tracepoints to mdt loader

[Bjorn Andersson]

On Mon 16 Nov 15:44 CST 2020, Rishabh Bhatnagar wrote:

> Add trace events to the mdt loader driver. These events
> can help us trace the region where we are loading the
> segments and the time it takes to initialize the image
> and setup the memory region.
> 
> Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
> ---
>  drivers/soc/qcom/mdt_loader.c     |  7 +++++++
>  include/trace/events/mdt_loader.h | 38 ++++++++++++++++++++++++++++++++++++++
>  2 files changed, 45 insertions(+)
>  create mode 100644 include/trace/events/mdt_loader.h
> 
> diff --git a/drivers/soc/qcom/mdt_loader.c b/drivers/soc/qcom/mdt_loader.c
> index 24cd193..96dc912 100644
> --- a/drivers/soc/qcom/mdt_loader.c
> +++ b/drivers/soc/qcom/mdt_loader.c
> @@ -17,6 +17,9 @@
>  #include <linux/slab.h>
>  #include <linux/soc/qcom/mdt_loader.h>
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/mdt_loader.h>
> +
>  static bool mdt_phdr_valid(const struct elf32_phdr *phdr)
>  {
>  	if (phdr->p_type != PT_LOAD)
> @@ -198,6 +201,7 @@ static int __qcom_mdt_load(struct device *dev, const struct firmware *fw,
>  		if (pas_init) {
>  			ret = qcom_scm_pas_mem_setup(pas_id, mem_phys,
>  						     max_addr - min_addr);
> +

This change is unnecessary.

>  			if (ret) {
>  				dev_err(dev, "unable to setup relocation\n");
>  				goto out;
> @@ -232,6 +236,7 @@ static int __qcom_mdt_load(struct device *dev, const struct firmware *fw,
>  
>  		ptr = mem_region + offset;
>  
> +

Ditto.

>  		if (phdr->p_filesz && phdr->p_offset < fw->size) {
>  			/* Firmware is large enough to be non-split */
>  			if (phdr->p_offset + phdr->p_filesz > fw->size) {
> @@ -256,6 +261,8 @@ static int __qcom_mdt_load(struct device *dev, const struct firmware *fw,
>  			release_firmware(seg_fw);
>  		}
>  
> +		trace_qcom_mdt_load_segment(mem_phys + offset, phdr->p_filesz,
> +					    fw_name);
>  		if (phdr->p_memsz > phdr->p_filesz)
>  			memset(ptr + phdr->p_filesz, 0, phdr->p_memsz - phdr->p_filesz);
>  	}
> diff --git a/include/trace/events/mdt_loader.h b/include/trace/events/mdt_loader.h
> new file mode 100644
> index 0000000..01c2461
> --- /dev/null
> +++ b/include/trace/events/mdt_loader.h
> @@ -0,0 +1,38 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright (c) 2020, The Linux Foundation. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM mdt_loader
> +
> +#if !defined(_TRACE_MDT_LOADER_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_MDT_LOADER_H
> +
> +#include <linux/types.h>
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT(qcom_mdt_load_segment,
> +
> +	TP_PROTO(phys_addr_t region_start, size_t region_size, const char *fw),
> +
> +	TP_ARGS(region_start, region_size, fw),
> +
> +	TP_STRUCT__entry(
> +		__field(phys_addr_t, region_start)
> +		__field(size_t, region_size)
> +		__string(fw, fw)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->region_start = region_start;
> +		__entry->region_size = region_size;
> +		__assign_str(fw, fw);
> +	),
> +
> +	TP_printk("firmware:%s region start=%pa size=%zx",
> +		  __get_str(fw), __entry->region_start, __entry->region_size)

Doesn't this printk use the normal format specifiers, where %pa should
be passed by reference? (I.e. shouldn't this be &__entry->region_start?)

Regards,
Bjorn

> +);
> +
> +#endif
> +#include <trace/define_trace.h>
> -- 
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
> 

[PATCH v2 2/3] firmware: scm: Add tracepoints to scm driver for pas calls

[Rishabh Bhatnagar]

Add trace events to the qcom_scm driver to trace pas calls.
These events can help us analyze the time impact for each scm
operation and can also serve as standard checkpoints in code.

Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
---
 drivers/firmware/qcom_scm.c     |  9 +++++++++
 include/trace/events/qcom_scm.h | 34 ++++++++++++++++++++++++++++++++++
 2 files changed, 43 insertions(+)
 create mode 100644 include/trace/events/qcom_scm.h

diff --git a/drivers/firmware/qcom_scm.c b/drivers/firmware/qcom_scm.c
index 7be48c1..5bc9b65 100644
--- a/drivers/firmware/qcom_scm.c
+++ b/drivers/firmware/qcom_scm.c
@@ -19,6 +19,9 @@
 
 #include "qcom_scm.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/qcom_scm.h>
+
 static bool download_mode = IS_ENABLED(CONFIG_QCOM_SCM_DOWNLOAD_MODE_DEFAULT);
 module_param(download_mode, bool, 0);
 
@@ -442,6 +445,7 @@ int qcom_scm_pas_init_image(u32 peripheral, const void *metadata, size_t size)
 	};
 	struct qcom_scm_res res;
 
+	trace_qcom_scm_call("Start scm_pas_init_image");
 	/*
 	 * During the scm call memory protection will be enabled for the meta
 	 * data blob, so make sure it's physically contiguous, 4K aligned and
@@ -467,6 +471,7 @@ int qcom_scm_pas_init_image(u32 peripheral, const void *metadata, size_t size)
 
 free_metadata:
 	dma_free_coherent(__scm->dev, size, mdata_buf, mdata_phys);
+	trace_qcom_scm_call("Complete scm_pas_init_image");
 
 	return ret ? : res.result[0];
 }
@@ -495,6 +500,7 @@ int qcom_scm_pas_mem_setup(u32 peripheral, phys_addr_t addr, phys_addr_t size)
 	};
 	struct qcom_scm_res res;
 
+	trace_qcom_scm_call("Start scm_pas_mem_setup");
 	ret = qcom_scm_clk_enable();
 	if (ret)
 		return ret;
@@ -502,6 +508,7 @@ int qcom_scm_pas_mem_setup(u32 peripheral, phys_addr_t addr, phys_addr_t size)
 	ret = qcom_scm_call(__scm->dev, &desc, &res);
 	qcom_scm_clk_disable();
 
+	trace_qcom_scm_call("Complete scm_pas_mem_setup");
 	return ret ? : res.result[0];
 }
 EXPORT_SYMBOL(qcom_scm_pas_mem_setup);
@@ -525,6 +532,7 @@ int qcom_scm_pas_auth_and_reset(u32 peripheral)
 	};
 	struct qcom_scm_res res;
 
+	trace_qcom_scm_call("Start auth_and_reset");
 	ret = qcom_scm_clk_enable();
 	if (ret)
 		return ret;
@@ -532,6 +540,7 @@ int qcom_scm_pas_auth_and_reset(u32 peripheral)
 	ret = qcom_scm_call(__scm->dev, &desc, &res);
 	qcom_scm_clk_disable();
 
+	trace_qcom_scm_call("Complete  auth_and_reset");
 	return ret ? : res.result[0];
 }
 EXPORT_SYMBOL(qcom_scm_pas_auth_and_reset);
diff --git a/include/trace/events/qcom_scm.h b/include/trace/events/qcom_scm.h
new file mode 100644
index 0000000..d918332
--- /dev/null
+++ b/include/trace/events/qcom_scm.h
@@ -0,0 +1,34 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2020, The Linux Foundation. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM qcom_scm
+
+#if !defined(_TRACE_QCOM_SCM_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_QCOM_SCM_H
+
+#include <linux/types.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(qcom_scm_call,
+
+	TP_PROTO(const char *event),
+
+	TP_ARGS(event),
+
+	TP_STRUCT__entry(
+		__string(event, event)
+	),
+
+	TP_fast_assign(
+		__assign_str(event, event);
+	),
+
+	TP_printk("qcom_scm_call event:%s", __get_str(event))
+);
+
+#endif
+#include <trace/define_trace.h>
+
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH v2 2/3] firmware: scm: Add tracepoints to scm driver for pas calls

[Bjorn Andersson]

On Mon 16 Nov 15:44 CST 2020, Rishabh Bhatnagar wrote:

> Add trace events to the qcom_scm driver to trace pas calls.
> These events can help us analyze the time impact for each scm
> operation and can also serve as standard checkpoints in code.
> 
> Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
> ---
>  drivers/firmware/qcom_scm.c     |  9 +++++++++
>  include/trace/events/qcom_scm.h | 34 ++++++++++++++++++++++++++++++++++
>  2 files changed, 43 insertions(+)
>  create mode 100644 include/trace/events/qcom_scm.h
> 
> diff --git a/drivers/firmware/qcom_scm.c b/drivers/firmware/qcom_scm.c
> index 7be48c1..5bc9b65 100644
> --- a/drivers/firmware/qcom_scm.c
> +++ b/drivers/firmware/qcom_scm.c
> @@ -19,6 +19,9 @@
>  
>  #include "qcom_scm.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/qcom_scm.h>
> +
>  static bool download_mode = IS_ENABLED(CONFIG_QCOM_SCM_DOWNLOAD_MODE_DEFAULT);
>  module_param(download_mode, bool, 0);
>  
> @@ -442,6 +445,7 @@ int qcom_scm_pas_init_image(u32 peripheral, const void *metadata, size_t size)
>  	};
>  	struct qcom_scm_res res;
>  
> +	trace_qcom_scm_call("Start scm_pas_init_image");

Please don't trace human readable strings into the trace buffer. Also,
aren't you curious about at least which @peripheral this was?

>  	/*
>  	 * During the scm call memory protection will be enabled for the meta
>  	 * data blob, so make sure it's physically contiguous, 4K aligned and
> @@ -467,6 +471,7 @@ int qcom_scm_pas_init_image(u32 peripheral, const void *metadata, size_t size)
>  
>  free_metadata:
>  	dma_free_coherent(__scm->dev, size, mdata_buf, mdata_phys);
> +	trace_qcom_scm_call("Complete scm_pas_init_image");

Wouldn't it be useful to know if this call succeeded?

>  
>  	return ret ? : res.result[0];
>  }
> @@ -495,6 +500,7 @@ int qcom_scm_pas_mem_setup(u32 peripheral, phys_addr_t addr, phys_addr_t size)
>  	};
>  	struct qcom_scm_res res;
>  
> +	trace_qcom_scm_call("Start scm_pas_mem_setup");

Wouldn't it be useful to know the @peripheral, @addr and @size here?

>  	ret = qcom_scm_clk_enable();
>  	if (ret)
>  		return ret;
> @@ -502,6 +508,7 @@ int qcom_scm_pas_mem_setup(u32 peripheral, phys_addr_t addr, phys_addr_t size)
>  	ret = qcom_scm_call(__scm->dev, &desc, &res);
>  	qcom_scm_clk_disable();
>  
> +	trace_qcom_scm_call("Complete scm_pas_mem_setup");

Ditto.

>  	return ret ? : res.result[0];
>  }
>  EXPORT_SYMBOL(qcom_scm_pas_mem_setup);
> @@ -525,6 +532,7 @@ int qcom_scm_pas_auth_and_reset(u32 peripheral)
>  	};
>  	struct qcom_scm_res res;
>  
> +	trace_qcom_scm_call("Start auth_and_reset");

Ditto.

>  	ret = qcom_scm_clk_enable();
>  	if (ret)
>  		return ret;
> @@ -532,6 +540,7 @@ int qcom_scm_pas_auth_and_reset(u32 peripheral)
>  	ret = qcom_scm_call(__scm->dev, &desc, &res);
>  	qcom_scm_clk_disable();
>  
> +	trace_qcom_scm_call("Complete  auth_and_reset");

Ditto.

>  	return ret ? : res.result[0];
>  }
>  EXPORT_SYMBOL(qcom_scm_pas_auth_and_reset);
> diff --git a/include/trace/events/qcom_scm.h b/include/trace/events/qcom_scm.h
> new file mode 100644
> index 0000000..d918332
> --- /dev/null
> +++ b/include/trace/events/qcom_scm.h
> @@ -0,0 +1,34 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright (c) 2020, The Linux Foundation. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM qcom_scm
> +
> +#if !defined(_TRACE_QCOM_SCM_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_QCOM_SCM_H
> +
> +#include <linux/types.h>
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT(qcom_scm_call,
> +
> +	TP_PROTO(const char *event),
> +
> +	TP_ARGS(event),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +	),
> +
> +	TP_printk("qcom_scm_call event:%s", __get_str(event))

We already know that this is the qcom_scm_call trace event, so no need
to include that in the trace data.

Regards,
Bjorn

> +);
> +
> +#endif
> +#include <trace/define_trace.h>
> +
> -- 
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
> 

[PATCH v2 3/3] remoteproc: Add ftrace events to trace lifecycle of remoteprocs

[Rishabh Bhatnagar]

Add trace events to trace bootup/shutdown/recovery of remote
processors. These events are useful in analyzing the time
spent in each step in the life cycle and can be used for
performace analysis. Also these serve as standard checkpoints
in debugging.

Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
---
 drivers/remoteproc/remoteproc_core.c | 19 +++++++-
 include/trace/events/remoteproc.h    | 91 ++++++++++++++++++++++++++++++++++++
 2 files changed, 109 insertions(+), 1 deletion(-)
 create mode 100644 include/trace/events/remoteproc.h

diff --git a/drivers/remoteproc/remoteproc_core.c b/drivers/remoteproc/remoteproc_core.c
index dab2c0f..39da409 100644
--- a/drivers/remoteproc/remoteproc_core.c
+++ b/drivers/remoteproc/remoteproc_core.c
@@ -42,6 +42,9 @@
 
 #include "remoteproc_internal.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/remoteproc.h>
+
 #define HIGH_BITS_MASK 0xFFFFFFFF00000000ULL
 
 static DEFINE_MUTEX(rproc_list_mutex);
@@ -1164,6 +1167,7 @@ static int rproc_prepare_subdevices(struct rproc *rproc)
 	struct rproc_subdev *subdev;
 	int ret;
 
+	trace_rproc_subdevices("Prepare subdevices", rproc->name);
 	list_for_each_entry(subdev, &rproc->subdevs, node) {
 		if (subdev->prepare) {
 			ret = subdev->prepare(subdev);
@@ -1188,6 +1192,7 @@ static int rproc_start_subdevices(struct rproc *rproc)
 	struct rproc_subdev *subdev;
 	int ret;
 
+	trace_rproc_subdevices("Start subdevices", rproc->name);
 	list_for_each_entry(subdev, &rproc->subdevs, node) {
 		if (subdev->start) {
 			ret = subdev->start(subdev);
@@ -1211,6 +1216,7 @@ static void rproc_stop_subdevices(struct rproc *rproc, bool crashed)
 {
 	struct rproc_subdev *subdev;
 
+	trace_rproc_subdevices("Stop subdevices", rproc->name);
 	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
 		if (subdev->stop)
 			subdev->stop(subdev, crashed);
@@ -1221,6 +1227,7 @@ static void rproc_unprepare_subdevices(struct rproc *rproc)
 {
 	struct rproc_subdev *subdev;
 
+	trace_rproc_subdevices("Unprepare subdevices", rproc->name);
 	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
 		if (subdev->unprepare)
 			subdev->unprepare(subdev);
@@ -1357,6 +1364,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
 	struct device *dev = &rproc->dev;
 	int ret;
 
+	trace_rproc_boot("loading firmware segments into memory", rproc->name);
 	/* load the ELF segments to memory */
 	ret = rproc_load_segments(rproc, fw);
 	if (ret) {
@@ -1385,6 +1393,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
 		goto reset_table_ptr;
 	}
 
+	trace_rproc_boot("starting remoteproc", rproc->name);
 	/* power up the remote processor */
 	ret = rproc->ops->start(rproc);
 	if (ret) {
@@ -1402,6 +1411,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
 
 	rproc->state = RPROC_RUNNING;
 
+	trace_rproc_boot("remoteproc is up", rproc->name);
 	dev_info(dev, "remote processor %s is now up\n", rproc->name);
 
 	return 0;
@@ -1648,6 +1658,7 @@ static int rproc_stop(struct rproc *rproc, bool crashed)
 	/* the installed resource table is no longer accessible */
 	rproc->table_ptr = rproc->cached_table;
 
+	trace_rproc_shutdown("Stopping the remoteproc", rproc->name);
 	/* power off the remote processor */
 	ret = rproc->ops->stop(rproc);
 	if (ret) {
@@ -1697,6 +1708,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
 	if (rproc->state != RPROC_CRASHED)
 		goto unlock_mutex;
 
+	trace_rproc_recovery("Recover remoteproc", rproc->name);
 	dev_err(dev, "recovering %s\n", rproc->name);
 
 	ret = rproc_stop(rproc, true);
@@ -1716,6 +1728,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
 	/* boot the remote processor up again */
 	ret = rproc_start(rproc, firmware_p);
 
+	trace_rproc_recovery("Recovery completed", rproc->name);
 	release_firmware(firmware_p);
 
 unlock_mutex:
@@ -1796,6 +1809,7 @@ int rproc_boot(struct rproc *rproc)
 	/* skip the boot or attach process if rproc is already powered up */
 	if (atomic_inc_return(&rproc->power) > 1) {
 		ret = 0;
+		trace_rproc_boot("Incrementing ref count and exiting", rproc->name);
 		goto unlock_mutex;
 	}
 
@@ -1804,6 +1818,7 @@ int rproc_boot(struct rproc *rproc)
 
 		ret = rproc_actuate(rproc);
 	} else {
+		trace_rproc_boot("requesting firmware", rproc->name);
 		dev_info(dev, "powering up %s\n", rproc->name);
 
 		/* load firmware */
@@ -1858,8 +1873,10 @@ void rproc_shutdown(struct rproc *rproc)
 	}
 
 	/* if the remote proc is still needed, bail out */
-	if (!atomic_dec_and_test(&rproc->power))
+	if (!atomic_dec_and_test(&rproc->power)) {
+		trace_rproc_shutdown("Decrementing ref count and exiting", rproc->name);
 		goto out;
+	}
 
 	ret = rproc_stop(rproc, false);
 	if (ret) {
diff --git a/include/trace/events/remoteproc.h b/include/trace/events/remoteproc.h
new file mode 100644
index 0000000..341bf4b
--- /dev/null
+++ b/include/trace/events/remoteproc.h
@@ -0,0 +1,91 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2020, The Linux Foundation. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM remoteproc
+
+#if !defined(_TRACE_REMOTEPROC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_REMOTEPROC_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(rproc_boot,
+
+	TP_PROTO(const char *event, const char *rproc_name),
+
+	TP_ARGS(event, rproc_name),
+
+	TP_STRUCT__entry(
+		__string(event, event)
+		__string(rproc_name, rproc_name)
+	),
+
+	TP_fast_assign(
+		__assign_str(event, event);
+		__assign_str(rproc_name, rproc_name);
+	),
+
+	TP_printk("rproc_boot: %s: %s", __get_str(rproc_name), __get_str(event))
+);
+
+TRACE_EVENT(rproc_shutdown,
+
+	TP_PROTO(const char *event, const char *rproc_name),
+
+	TP_ARGS(event, rproc_name),
+
+	TP_STRUCT__entry(
+		__string(event, event)
+		__string(rproc_name, rproc_name)
+	),
+
+	TP_fast_assign(
+		__assign_str(event, event);
+		__assign_str(rproc_name, rproc_name);
+	),
+
+	TP_printk("rproc_shutdown: %s: %s", __get_str(rproc_name), __get_str(event))
+);
+
+TRACE_EVENT(rproc_recovery,
+
+	TP_PROTO(const char *event, const char *rproc_name),
+
+	TP_ARGS(event, rproc_name),
+
+	TP_STRUCT__entry(
+		__string(event, event)
+		__string(rproc_name, rproc_name)
+	),
+
+	TP_fast_assign(
+		__assign_str(event, event);
+		__assign_str(rproc_name, rproc_name);
+	),
+
+	TP_printk("rproc_recovery: %s: %s", __get_str(rproc_name), __get_str(event))
+);
+
+TRACE_EVENT(rproc_subdevices,
+
+	TP_PROTO(const char *event, const char *rproc_name),
+
+	TP_ARGS(event, rproc_name),
+
+	TP_STRUCT__entry(
+		__string(event, event)
+		__string(rproc_name, rproc_name)
+	),
+
+	TP_fast_assign(
+		__assign_str(event, event);
+		__assign_str(rproc_name, rproc_name);
+	),
+
+	TP_printk("rproc_subdevices: %s: %s", __get_str(rproc_name), __get_str(event))
+);
+#endif
+#include <trace/define_trace.h>
+
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH v2 3/3] remoteproc: Add ftrace events to trace lifecycle of remoteprocs

[Mathieu Poirier]

On Mon, Nov 16, 2020 at 01:44:44PM -0800, Rishabh Bhatnagar wrote:
> Add trace events to trace bootup/shutdown/recovery of remote
> processors. These events are useful in analyzing the time
> spent in each step in the life cycle and can be used for
> performace analysis. Also these serve as standard checkpoints
> in debugging.
> 
> Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
> ---
>  drivers/remoteproc/remoteproc_core.c | 19 +++++++-
>  include/trace/events/remoteproc.h    | 91 ++++++++++++++++++++++++++++++++++++
>  2 files changed, 109 insertions(+), 1 deletion(-)
>  create mode 100644 include/trace/events/remoteproc.h
> 
> diff --git a/drivers/remoteproc/remoteproc_core.c b/drivers/remoteproc/remoteproc_core.c
> index dab2c0f..39da409 100644
> --- a/drivers/remoteproc/remoteproc_core.c
> +++ b/drivers/remoteproc/remoteproc_core.c
> @@ -42,6 +42,9 @@
>  
>  #include "remoteproc_internal.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/remoteproc.h>
> +
>  #define HIGH_BITS_MASK 0xFFFFFFFF00000000ULL
>  
>  static DEFINE_MUTEX(rproc_list_mutex);
> @@ -1164,6 +1167,7 @@ static int rproc_prepare_subdevices(struct rproc *rproc)
>  	struct rproc_subdev *subdev;
>  	int ret;
>  
> +	trace_rproc_subdevices("Prepare subdevices", rproc->name);

I wouldn't add this to the core - after a while they become part of the ABI and
we can't move things around.  I suppose they can stay in platform drivers but
even that is going against the general trend in the kernel community to avoid them at
all.  To me this should remain out of tree code but Bjorn will make the call.

Thanks,
Mathieu

>  	list_for_each_entry(subdev, &rproc->subdevs, node) {
>  		if (subdev->prepare) {
>  			ret = subdev->prepare(subdev);
> @@ -1188,6 +1192,7 @@ static int rproc_start_subdevices(struct rproc *rproc)
>  	struct rproc_subdev *subdev;
>  	int ret;
>  
> +	trace_rproc_subdevices("Start subdevices", rproc->name);
>  	list_for_each_entry(subdev, &rproc->subdevs, node) {
>  		if (subdev->start) {
>  			ret = subdev->start(subdev);
> @@ -1211,6 +1216,7 @@ static void rproc_stop_subdevices(struct rproc *rproc, bool crashed)
>  {
>  	struct rproc_subdev *subdev;
>  
> +	trace_rproc_subdevices("Stop subdevices", rproc->name);
>  	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
>  		if (subdev->stop)
>  			subdev->stop(subdev, crashed);
> @@ -1221,6 +1227,7 @@ static void rproc_unprepare_subdevices(struct rproc *rproc)
>  {
>  	struct rproc_subdev *subdev;
>  
> +	trace_rproc_subdevices("Unprepare subdevices", rproc->name);
>  	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
>  		if (subdev->unprepare)
>  			subdev->unprepare(subdev);
> @@ -1357,6 +1364,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
>  	struct device *dev = &rproc->dev;
>  	int ret;
>  
> +	trace_rproc_boot("loading firmware segments into memory", rproc->name);
>  	/* load the ELF segments to memory */
>  	ret = rproc_load_segments(rproc, fw);
>  	if (ret) {
> @@ -1385,6 +1393,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
>  		goto reset_table_ptr;
>  	}
>  
> +	trace_rproc_boot("starting remoteproc", rproc->name);
>  	/* power up the remote processor */
>  	ret = rproc->ops->start(rproc);
>  	if (ret) {
> @@ -1402,6 +1411,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
>  
>  	rproc->state = RPROC_RUNNING;
>  
> +	trace_rproc_boot("remoteproc is up", rproc->name);
>  	dev_info(dev, "remote processor %s is now up\n", rproc->name);
>  
>  	return 0;
> @@ -1648,6 +1658,7 @@ static int rproc_stop(struct rproc *rproc, bool crashed)
>  	/* the installed resource table is no longer accessible */
>  	rproc->table_ptr = rproc->cached_table;
>  
> +	trace_rproc_shutdown("Stopping the remoteproc", rproc->name);
>  	/* power off the remote processor */
>  	ret = rproc->ops->stop(rproc);
>  	if (ret) {
> @@ -1697,6 +1708,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
>  	if (rproc->state != RPROC_CRASHED)
>  		goto unlock_mutex;
>  
> +	trace_rproc_recovery("Recover remoteproc", rproc->name);
>  	dev_err(dev, "recovering %s\n", rproc->name);
>  
>  	ret = rproc_stop(rproc, true);
> @@ -1716,6 +1728,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
>  	/* boot the remote processor up again */
>  	ret = rproc_start(rproc, firmware_p);
>  
> +	trace_rproc_recovery("Recovery completed", rproc->name);
>  	release_firmware(firmware_p);
>  
>  unlock_mutex:
> @@ -1796,6 +1809,7 @@ int rproc_boot(struct rproc *rproc)
>  	/* skip the boot or attach process if rproc is already powered up */
>  	if (atomic_inc_return(&rproc->power) > 1) {
>  		ret = 0;
> +		trace_rproc_boot("Incrementing ref count and exiting", rproc->name);
>  		goto unlock_mutex;
>  	}
>  
> @@ -1804,6 +1818,7 @@ int rproc_boot(struct rproc *rproc)
>  
>  		ret = rproc_actuate(rproc);
>  	} else {
> +		trace_rproc_boot("requesting firmware", rproc->name);
>  		dev_info(dev, "powering up %s\n", rproc->name);
>  
>  		/* load firmware */
> @@ -1858,8 +1873,10 @@ void rproc_shutdown(struct rproc *rproc)
>  	}
>  
>  	/* if the remote proc is still needed, bail out */
> -	if (!atomic_dec_and_test(&rproc->power))
> +	if (!atomic_dec_and_test(&rproc->power)) {
> +		trace_rproc_shutdown("Decrementing ref count and exiting", rproc->name);
>  		goto out;
> +	}
>  
>  	ret = rproc_stop(rproc, false);
>  	if (ret) {
> diff --git a/include/trace/events/remoteproc.h b/include/trace/events/remoteproc.h
> new file mode 100644
> index 0000000..341bf4b
> --- /dev/null
> +++ b/include/trace/events/remoteproc.h
> @@ -0,0 +1,91 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright (c) 2020, The Linux Foundation. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM remoteproc
> +
> +#if !defined(_TRACE_REMOTEPROC_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_REMOTEPROC_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT(rproc_boot,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_boot: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +
> +TRACE_EVENT(rproc_shutdown,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_shutdown: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +
> +TRACE_EVENT(rproc_recovery,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_recovery: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +
> +TRACE_EVENT(rproc_subdevices,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_subdevices: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +#endif
> +#include <trace/define_trace.h>
> +
> -- 
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
> 

Re: [PATCH v2 3/3] remoteproc: Add ftrace events to trace lifecycle of remoteprocs

[Bjorn Andersson]

On Wed 18 Nov 16:26 CST 2020, Mathieu Poirier wrote:

> On Mon, Nov 16, 2020 at 01:44:44PM -0800, Rishabh Bhatnagar wrote:
> > Add trace events to trace bootup/shutdown/recovery of remote
> > processors. These events are useful in analyzing the time
> > spent in each step in the life cycle and can be used for
> > performace analysis. Also these serve as standard checkpoints
> > in debugging.
> > 
> > Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
> > ---
> >  drivers/remoteproc/remoteproc_core.c | 19 +++++++-
> >  include/trace/events/remoteproc.h    | 91 ++++++++++++++++++++++++++++++++++++
> >  2 files changed, 109 insertions(+), 1 deletion(-)
> >  create mode 100644 include/trace/events/remoteproc.h
> > 
> > diff --git a/drivers/remoteproc/remoteproc_core.c b/drivers/remoteproc/remoteproc_core.c
> > index dab2c0f..39da409 100644
> > --- a/drivers/remoteproc/remoteproc_core.c
> > +++ b/drivers/remoteproc/remoteproc_core.c
> > @@ -42,6 +42,9 @@
> >  
> >  #include "remoteproc_internal.h"
> >  
> > +#define CREATE_TRACE_POINTS
> > +#include <trace/events/remoteproc.h>
> > +
> >  #define HIGH_BITS_MASK 0xFFFFFFFF00000000ULL
> >  
> >  static DEFINE_MUTEX(rproc_list_mutex);
> > @@ -1164,6 +1167,7 @@ static int rproc_prepare_subdevices(struct rproc *rproc)
> >  	struct rproc_subdev *subdev;
> >  	int ret;
> >  
> > +	trace_rproc_subdevices("Prepare subdevices", rproc->name);
> 
> I wouldn't add this to the core - after a while they become part of the ABI and
> we can't move things around.  I suppose they can stay in platform drivers but
> even that is going against the general trend in the kernel community to avoid them at
> all.  To me this should remain out of tree code but Bjorn will make the call.
> 

I need to update my understanding of traces being ABI or not. But I
think the general start/stop traces would be useful and I expect that we
will continue to do those.

For the subdevices we need to conclude what we want to trace, e.g.
is this big trace adding anything beyond the trace_rproc_boot()?
Shouldn't we trace the individual subdevs, and if so we're definitely in
the area you're worrying about.

Regards,
Bjorn

> Thanks,
> Mathieu
> 
> >  	list_for_each_entry(subdev, &rproc->subdevs, node) {
> >  		if (subdev->prepare) {
> >  			ret = subdev->prepare(subdev);
> > @@ -1188,6 +1192,7 @@ static int rproc_start_subdevices(struct rproc *rproc)
> >  	struct rproc_subdev *subdev;
> >  	int ret;
> >  
> > +	trace_rproc_subdevices("Start subdevices", rproc->name);
> >  	list_for_each_entry(subdev, &rproc->subdevs, node) {
> >  		if (subdev->start) {
> >  			ret = subdev->start(subdev);
> > @@ -1211,6 +1216,7 @@ static void rproc_stop_subdevices(struct rproc *rproc, bool crashed)
> >  {
> >  	struct rproc_subdev *subdev;
> >  
> > +	trace_rproc_subdevices("Stop subdevices", rproc->name);
> >  	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
> >  		if (subdev->stop)
> >  			subdev->stop(subdev, crashed);
> > @@ -1221,6 +1227,7 @@ static void rproc_unprepare_subdevices(struct rproc *rproc)
> >  {
> >  	struct rproc_subdev *subdev;
> >  
> > +	trace_rproc_subdevices("Unprepare subdevices", rproc->name);
> >  	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
> >  		if (subdev->unprepare)
> >  			subdev->unprepare(subdev);
> > @@ -1357,6 +1364,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
> >  	struct device *dev = &rproc->dev;
> >  	int ret;
> >  
> > +	trace_rproc_boot("loading firmware segments into memory", rproc->name);
> >  	/* load the ELF segments to memory */
> >  	ret = rproc_load_segments(rproc, fw);
> >  	if (ret) {
> > @@ -1385,6 +1393,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
> >  		goto reset_table_ptr;
> >  	}
> >  
> > +	trace_rproc_boot("starting remoteproc", rproc->name);
> >  	/* power up the remote processor */
> >  	ret = rproc->ops->start(rproc);
> >  	if (ret) {
> > @@ -1402,6 +1411,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
> >  
> >  	rproc->state = RPROC_RUNNING;
> >  
> > +	trace_rproc_boot("remoteproc is up", rproc->name);
> >  	dev_info(dev, "remote processor %s is now up\n", rproc->name);
> >  
> >  	return 0;
> > @@ -1648,6 +1658,7 @@ static int rproc_stop(struct rproc *rproc, bool crashed)
> >  	/* the installed resource table is no longer accessible */
> >  	rproc->table_ptr = rproc->cached_table;
> >  
> > +	trace_rproc_shutdown("Stopping the remoteproc", rproc->name);
> >  	/* power off the remote processor */
> >  	ret = rproc->ops->stop(rproc);
> >  	if (ret) {
> > @@ -1697,6 +1708,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
> >  	if (rproc->state != RPROC_CRASHED)
> >  		goto unlock_mutex;
> >  
> > +	trace_rproc_recovery("Recover remoteproc", rproc->name);
> >  	dev_err(dev, "recovering %s\n", rproc->name);
> >  
> >  	ret = rproc_stop(rproc, true);
> > @@ -1716,6 +1728,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
> >  	/* boot the remote processor up again */
> >  	ret = rproc_start(rproc, firmware_p);
> >  
> > +	trace_rproc_recovery("Recovery completed", rproc->name);
> >  	release_firmware(firmware_p);
> >  
> >  unlock_mutex:
> > @@ -1796,6 +1809,7 @@ int rproc_boot(struct rproc *rproc)
> >  	/* skip the boot or attach process if rproc is already powered up */
> >  	if (atomic_inc_return(&rproc->power) > 1) {
> >  		ret = 0;
> > +		trace_rproc_boot("Incrementing ref count and exiting", rproc->name);
> >  		goto unlock_mutex;
> >  	}
> >  
> > @@ -1804,6 +1818,7 @@ int rproc_boot(struct rproc *rproc)
> >  
> >  		ret = rproc_actuate(rproc);
> >  	} else {
> > +		trace_rproc_boot("requesting firmware", rproc->name);
> >  		dev_info(dev, "powering up %s\n", rproc->name);
> >  
> >  		/* load firmware */
> > @@ -1858,8 +1873,10 @@ void rproc_shutdown(struct rproc *rproc)
> >  	}
> >  
> >  	/* if the remote proc is still needed, bail out */
> > -	if (!atomic_dec_and_test(&rproc->power))
> > +	if (!atomic_dec_and_test(&rproc->power)) {
> > +		trace_rproc_shutdown("Decrementing ref count and exiting", rproc->name);
> >  		goto out;
> > +	}
> >  
> >  	ret = rproc_stop(rproc, false);
> >  	if (ret) {
> > diff --git a/include/trace/events/remoteproc.h b/include/trace/events/remoteproc.h
> > new file mode 100644
> > index 0000000..341bf4b
> > --- /dev/null
> > +++ b/include/trace/events/remoteproc.h
> > @@ -0,0 +1,91 @@
> > +/* SPDX-License-Identifier: GPL-2.0-only */
> > +/*
> > + * Copyright (c) 2020, The Linux Foundation. All rights reserved.
> > + */
> > +
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM remoteproc
> > +
> > +#if !defined(_TRACE_REMOTEPROC_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_REMOTEPROC_H
> > +
> > +#include <linux/tracepoint.h>
> > +
> > +TRACE_EVENT(rproc_boot,
> > +
> > +	TP_PROTO(const char *event, const char *rproc_name),
> > +
> > +	TP_ARGS(event, rproc_name),
> > +
> > +	TP_STRUCT__entry(
> > +		__string(event, event)
> > +		__string(rproc_name, rproc_name)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__assign_str(event, event);
> > +		__assign_str(rproc_name, rproc_name);
> > +	),
> > +
> > +	TP_printk("rproc_boot: %s: %s", __get_str(rproc_name), __get_str(event))
> > +);
> > +
> > +TRACE_EVENT(rproc_shutdown,
> > +
> > +	TP_PROTO(const char *event, const char *rproc_name),
> > +
> > +	TP_ARGS(event, rproc_name),
> > +
> > +	TP_STRUCT__entry(
> > +		__string(event, event)
> > +		__string(rproc_name, rproc_name)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__assign_str(event, event);
> > +		__assign_str(rproc_name, rproc_name);
> > +	),
> > +
> > +	TP_printk("rproc_shutdown: %s: %s", __get_str(rproc_name), __get_str(event))
> > +);
> > +
> > +TRACE_EVENT(rproc_recovery,
> > +
> > +	TP_PROTO(const char *event, const char *rproc_name),
> > +
> > +	TP_ARGS(event, rproc_name),
> > +
> > +	TP_STRUCT__entry(
> > +		__string(event, event)
> > +		__string(rproc_name, rproc_name)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__assign_str(event, event);
> > +		__assign_str(rproc_name, rproc_name);
> > +	),
> > +
> > +	TP_printk("rproc_recovery: %s: %s", __get_str(rproc_name), __get_str(event))
> > +);
> > +
> > +TRACE_EVENT(rproc_subdevices,
> > +
> > +	TP_PROTO(const char *event, const char *rproc_name),
> > +
> > +	TP_ARGS(event, rproc_name),
> > +
> > +	TP_STRUCT__entry(
> > +		__string(event, event)
> > +		__string(rproc_name, rproc_name)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__assign_str(event, event);
> > +		__assign_str(rproc_name, rproc_name);
> > +	),
> > +
> > +	TP_printk("rproc_subdevices: %s: %s", __get_str(rproc_name), __get_str(event))
> > +);
> > +#endif
> > +#include <trace/define_trace.h>
> > +
> > -- 
> > The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> > a Linux Foundation Collaborative Project
> > 

Re: [PATCH v2 3/3] remoteproc: Add ftrace events to trace lifecycle of remoteprocs

[Bjorn Andersson]

On Mon 16 Nov 15:44 CST 2020, Rishabh Bhatnagar wrote:

> Add trace events to trace bootup/shutdown/recovery of remote
> processors. These events are useful in analyzing the time
> spent in each step in the life cycle and can be used for
> performace analysis. Also these serve as standard checkpoints
> in debugging.
> 
> Signed-off-by: Rishabh Bhatnagar <rishabhb@codeaurora.org>
> ---
>  drivers/remoteproc/remoteproc_core.c | 19 +++++++-
>  include/trace/events/remoteproc.h    | 91 ++++++++++++++++++++++++++++++++++++
>  2 files changed, 109 insertions(+), 1 deletion(-)
>  create mode 100644 include/trace/events/remoteproc.h
> 
> diff --git a/drivers/remoteproc/remoteproc_core.c b/drivers/remoteproc/remoteproc_core.c
> index dab2c0f..39da409 100644
> --- a/drivers/remoteproc/remoteproc_core.c
> +++ b/drivers/remoteproc/remoteproc_core.c
> @@ -42,6 +42,9 @@
>  
>  #include "remoteproc_internal.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/remoteproc.h>
> +
>  #define HIGH_BITS_MASK 0xFFFFFFFF00000000ULL
>  
>  static DEFINE_MUTEX(rproc_list_mutex);
> @@ -1164,6 +1167,7 @@ static int rproc_prepare_subdevices(struct rproc *rproc)
>  	struct rproc_subdev *subdev;
>  	int ret;
>  
> +	trace_rproc_subdevices("Prepare subdevices", rproc->name);

Please use specific trace events, rather than these trace_printk() like
ones.

>  	list_for_each_entry(subdev, &rproc->subdevs, node) {
>  		if (subdev->prepare) {
>  			ret = subdev->prepare(subdev);
> @@ -1188,6 +1192,7 @@ static int rproc_start_subdevices(struct rproc *rproc)
>  	struct rproc_subdev *subdev;
>  	int ret;
>  
> +	trace_rproc_subdevices("Start subdevices", rproc->name);
>  	list_for_each_entry(subdev, &rproc->subdevs, node) {
>  		if (subdev->start) {
>  			ret = subdev->start(subdev);
> @@ -1211,6 +1216,7 @@ static void rproc_stop_subdevices(struct rproc *rproc, bool crashed)
>  {
>  	struct rproc_subdev *subdev;
>  
> +	trace_rproc_subdevices("Stop subdevices", rproc->name);
>  	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
>  		if (subdev->stop)
>  			subdev->stop(subdev, crashed);
> @@ -1221,6 +1227,7 @@ static void rproc_unprepare_subdevices(struct rproc *rproc)
>  {
>  	struct rproc_subdev *subdev;
>  
> +	trace_rproc_subdevices("Unprepare subdevices", rproc->name);
>  	list_for_each_entry_reverse(subdev, &rproc->subdevs, node) {
>  		if (subdev->unprepare)
>  			subdev->unprepare(subdev);
> @@ -1357,6 +1364,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
>  	struct device *dev = &rproc->dev;
>  	int ret;
>  
> +	trace_rproc_boot("loading firmware segments into memory", rproc->name);
>  	/* load the ELF segments to memory */
>  	ret = rproc_load_segments(rproc, fw);
>  	if (ret) {
> @@ -1385,6 +1393,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
>  		goto reset_table_ptr;
>  	}
>  
> +	trace_rproc_boot("starting remoteproc", rproc->name);
>  	/* power up the remote processor */
>  	ret = rproc->ops->start(rproc);
>  	if (ret) {
> @@ -1402,6 +1411,7 @@ static int rproc_start(struct rproc *rproc, const struct firmware *fw)
>  
>  	rproc->state = RPROC_RUNNING;
>  
> +	trace_rproc_boot("remoteproc is up", rproc->name);
>  	dev_info(dev, "remote processor %s is now up\n", rproc->name);
>  
>  	return 0;
> @@ -1648,6 +1658,7 @@ static int rproc_stop(struct rproc *rproc, bool crashed)
>  	/* the installed resource table is no longer accessible */
>  	rproc->table_ptr = rproc->cached_table;
>  
> +	trace_rproc_shutdown("Stopping the remoteproc", rproc->name);
>  	/* power off the remote processor */
>  	ret = rproc->ops->stop(rproc);
>  	if (ret) {
> @@ -1697,6 +1708,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
>  	if (rproc->state != RPROC_CRASHED)
>  		goto unlock_mutex;
>  
> +	trace_rproc_recovery("Recover remoteproc", rproc->name);
>  	dev_err(dev, "recovering %s\n", rproc->name);
>  
>  	ret = rproc_stop(rproc, true);
> @@ -1716,6 +1728,7 @@ int rproc_trigger_recovery(struct rproc *rproc)
>  	/* boot the remote processor up again */
>  	ret = rproc_start(rproc, firmware_p);
>  
> +	trace_rproc_recovery("Recovery completed", rproc->name);
>  	release_firmware(firmware_p);
>  
>  unlock_mutex:
> @@ -1796,6 +1809,7 @@ int rproc_boot(struct rproc *rproc)
>  	/* skip the boot or attach process if rproc is already powered up */
>  	if (atomic_inc_return(&rproc->power) > 1) {
>  		ret = 0;
> +		trace_rproc_boot("Incrementing ref count and exiting", rproc->name);

Why tracing only this case? If you really would like to know if this
ends up booting the core or not perhaps we could include the refcount in
the event?

>  		goto unlock_mutex;
>  	}
>  
> @@ -1804,6 +1818,7 @@ int rproc_boot(struct rproc *rproc)
>  
>  		ret = rproc_actuate(rproc);
>  	} else {
> +		trace_rproc_boot("requesting firmware", rproc->name);

I can see how this would be useful, but don't you want to know the
firmware name? And why not just include it in the trace_rproc_boot event?

>  		dev_info(dev, "powering up %s\n", rproc->name);
>  
>  		/* load firmware */
> @@ -1858,8 +1873,10 @@ void rproc_shutdown(struct rproc *rproc)
>  	}
>  
>  	/* if the remote proc is still needed, bail out */
> -	if (!atomic_dec_and_test(&rproc->power))
> +	if (!atomic_dec_and_test(&rproc->power)) {
> +		trace_rproc_shutdown("Decrementing ref count and exiting", rproc->name);

As above, why not trace all calls to rproc_shutdown()?

>  		goto out;
> +	}
>  
>  	ret = rproc_stop(rproc, false);
>  	if (ret) {
> diff --git a/include/trace/events/remoteproc.h b/include/trace/events/remoteproc.h
> new file mode 100644
> index 0000000..341bf4b
> --- /dev/null
> +++ b/include/trace/events/remoteproc.h
> @@ -0,0 +1,91 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright (c) 2020, The Linux Foundation. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM remoteproc
> +
> +#if !defined(_TRACE_REMOTEPROC_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_REMOTEPROC_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT(rproc_boot,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_boot: %s: %s", __get_str(rproc_name), __get_str(event))

As with the other patch, please don't duplicate the event name in the
printk format.

Regards,
Bjorn

> +);
> +
> +TRACE_EVENT(rproc_shutdown,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_shutdown: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +
> +TRACE_EVENT(rproc_recovery,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_recovery: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +
> +TRACE_EVENT(rproc_subdevices,
> +
> +	TP_PROTO(const char *event, const char *rproc_name),
> +
> +	TP_ARGS(event, rproc_name),
> +
> +	TP_STRUCT__entry(
> +		__string(event, event)
> +		__string(rproc_name, rproc_name)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(event, event);
> +		__assign_str(rproc_name, rproc_name);
> +	),
> +
> +	TP_printk("rproc_subdevices: %s: %s", __get_str(rproc_name), __get_str(event))
> +);
> +#endif
> +#include <trace/define_trace.h>
> +
> -- 
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
>