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@xxxxxxxxxxxxxx>
> ---
> 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
>
