This is an automated email from the ASF dual-hosted git repository.
xiaoxiang pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-nuttx-apps.git
The following commit(s) were added to refs/heads/master by this push:
new 954c90b Add SCHED_INSTRUMENTATION_HIRES support
954c90b is described below
commit 954c90b4b554ab534ddb2b51d9c328ee48332a7b
Author: Nakamura, Yuuichi <[email protected]>
AuthorDate: Mon Oct 5 14:54:25 2020 +0900
Add SCHED_INSTRUMENTATION_HIRES support
---
system/sched_note/note_main.c | 234 ++++++++++++++++++++++++------------------
system/trace/trace_dump.c | 18 +++-
2 files changed, 152 insertions(+), 100 deletions(-)
diff --git a/system/sched_note/note_main.c b/system/sched_note/note_main.c
index 7f16350..09d5e58 100644
--- a/system/sched_note/note_main.c
+++ b/system/sched_note/note_main.c
@@ -36,6 +36,22 @@
#include <nuttx/sched_note.h>
/************************************************************************************
+ * Pre-processor Definitions
+
************************************************************************************/
+
+#ifdef CONFIG_SCHED_INSTRUMENTATION_HIRES
+# define syslog_time(priority, fmt, ...) \
+ syslog(priority, "%08lx.%08lx: " fmt, \
+ (unsigned long)systime_sec, (unsigned long)systime_nsec, \
+ __VA_ARGS__)
+#else
+# define syslog_time(priority, fmt, ...) \
+ syslog(priority, "%08lx: " fmt, \
+ (unsigned long)systime, \
+ __VA_ARGS__)
+#endif
+
+/************************************************************************************
* Private Data
************************************************************************************/
@@ -72,7 +88,12 @@ static FAR const char *g_statenames[] =
static void dump_notes(size_t nread)
{
FAR struct note_common_s *note;
+#ifdef CONFIG_SCHED_INSTRUMENTATION_HIRES
+ uint32_t systime_sec;
+ uint32_t systime_nsec;
+#else
uint32_t systime;
+#endif
pid_t pid;
off_t offset;
@@ -82,10 +103,21 @@ static void dump_notes(size_t nread)
note = (FAR struct note_common_s *)&g_note_buffer[offset];
pid = (pid_t)note->nc_pid[0] +
((pid_t)note->nc_pid[1] << 8);
+#ifdef CONFIG_SCHED_INSTRUMENTATION_HIRES
+ systime_nsec = (uint32_t)note->nc_systime_nsec[0] +
+ (uint32_t)(note->nc_systime_nsec[1] << 8) +
+ (uint32_t)(note->nc_systime_nsec[2] << 16) +
+ (uint32_t)(note->nc_systime_nsec[3] << 24);
+ systime_sec = (uint32_t)note->nc_systime_sec[0] +
+ (uint32_t)(note->nc_systime_sec[1] << 8) +
+ (uint32_t)(note->nc_systime_sec[2] << 16) +
+ (uint32_t)(note->nc_systime_sec[3] << 24);
+#else
systime = (uint32_t) note->nc_systime[0] +
(uint32_t)(note->nc_systime[1] << 8) +
(uint32_t)(note->nc_systime[2] << 16) +
(uint32_t)(note->nc_systime[3] << 24);
+#endif
switch (note->nc_type)
{
@@ -104,24 +136,28 @@ static void dump_notes(size_t nread)
#ifdef CONFIG_SMP
#if CONFIG_TASK_NAME_SIZE > 0
- syslog(LOG_INFO, "%08lx: Task %u \"%s\" started, CPU%u, priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u \"%s\" started, CPU%u, priority %u\n",
+ (unsigned int)pid,
note_start->nst_name, (unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority);
#else
- syslog(LOG_INFO, "%08lx: Task %u started, CPU%u, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u started, CPU%u, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority);
#endif
#else
#if CONFIG_TASK_NAME_SIZE > 0
- syslog(LOG_INFO, "%08lx: Task %u \"%s\" started, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u \"%s\" started, priority %u\n",
+ (unsigned int)pid,
note_start->nst_name, (unsigned int)note->nc_priority);
#else
- syslog(LOG_INFO, "%08lx: Task %u started, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u started, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority);
#endif
#endif
@@ -139,14 +175,14 @@ static void dump_notes(size_t nread)
}
#ifdef CONFIG_SMP
- syslog(LOG_INFO,
- "%08lx: Task %u stopped, CPU%u, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u stopped, CPU%u, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu, (unsigned
int)note->nc_priority);
#else
- syslog(LOG_INFO,
- "%08lx: Task %u stopped, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u stopped, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority);
#endif
}
@@ -176,15 +212,15 @@ static void dump_notes(size_t nread)
}
#ifdef CONFIG_SMP
- syslog(LOG_INFO,
- "%08lx: Task %u suspended, CPU%u, priority %u, state
\"%s\"\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u suspended, CPU%u, priority %u, state \"%s\"\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority, statename);
#else
- syslog(LOG_INFO,
- "%08lx: Task %u suspended, priority %u, state \"%s\"\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u suspended, priority %u, state \"%s\"\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority, statename);
#endif
}
@@ -201,15 +237,15 @@ static void dump_notes(size_t nread)
}
#ifdef CONFIG_SMP
- syslog(LOG_INFO,
- "%08lx: Task %u resumed, CPU%u, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u resumed, CPU%u, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority);
#else
- syslog(LOG_INFO,
- "%08lx: Task %u resumed, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u resumed, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority);
#endif
}
@@ -229,9 +265,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u requests CPU%u to start, priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u requests CPU%u to start, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note_start->ncs_target,
(unsigned int)note->nc_priority);
@@ -248,9 +284,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u has started, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u has started, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority);
}
@@ -269,9 +305,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u requests CPU%u to pause, priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u requests CPU%u to pause, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note_pause->ncp_target,
(unsigned int)note->nc_priority);
@@ -288,9 +324,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u has paused, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u has paused, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority);
}
@@ -309,9 +345,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u requests CPU%u to resume, priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u requests CPU%u to resume, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note_resume->ncr_target,
(unsigned int)note->nc_priority);
@@ -328,9 +364,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u has resumed, priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u has resumed, priority %u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority);
}
@@ -359,30 +395,30 @@ static void dump_notes(size_t nread)
if (note->nc_type == NOTE_PREEMPT_LOCK)
{
#ifdef CONFIG_SMP
- syslog(LOG_INFO,
- "%08lx: Task %u locked, CPU%u, priority %u,
count=%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u locked, CPU%u, priority %u, count=%u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority, (unsigned int)count);
#else
- syslog(LOG_INFO,
- "%08lx: Task %u locked, priority %u, count=%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u locked, priority %u, count=%u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority, (unsigned int)count);
#endif
}
else
{
#ifdef CONFIG_SMP
- syslog(LOG_INFO,
- "%08lx: Task %u unlocked, CPU%u, priority %u,
count=%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u unlocked, CPU%u, priority %u, count=%u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority, (unsigned int)count);
#else
- syslog(LOG_INFO,
- "%08lx: Task %u unlocked, priority %u, count=%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u unlocked, priority %u, count=%u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority, (unsigned int)count);
#endif
}
@@ -415,33 +451,33 @@ static void dump_notes(size_t nread)
if (note->nc_type == NOTE_CSECTION_ENTER)
{
- syslog(LOG_INFO,
- "%08lx: Task %u enter csection, CPU%u, priority %u, "
+ syslog_time(LOG_INFO,
+ "Task %u enter csection, CPU%u, priority %u, "
"count=%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority, (unsigned int)count);
}
else
{
- syslog(LOG_INFO,
- "%08lx: Task %u leave csection, CPU%u, priority %u, "
+ syslog_time(LOG_INFO,
+ "Task %u leave csection, CPU%u, priority %u, "
"count=%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
(unsigned int)note->nc_priority, (unsigned int)count);
}
#else
if (note->nc_type == NOTE_CSECTION_ENTER)
{
- syslog(LOG_INFO, "%08lx: Task %u enter csection, priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO, "Task %u enter csection, priority
%u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority);
}
else
{
- syslog(LOG_INFO, "%08lx: Task %u leave csection, priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO, "Task %u leave csection, priority
%u\n",
+ (unsigned int)pid,
(unsigned int)note->nc_priority);
}
#endif
@@ -487,10 +523,10 @@ static void dump_notes(size_t nread)
#ifdef CONFIG_SMP
case NOTE_SPINLOCK_LOCK:
{
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u wait for spinlock=%p value=%u
"
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u wait for spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
spinlock,
(unsigned int)note_spinlock->nsp_value,
@@ -500,10 +536,10 @@ static void dump_notes(size_t nread)
case NOTE_SPINLOCK_LOCKED:
{
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u has spinlock=%p value=%u "
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u has spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
spinlock,
(unsigned int)note_spinlock->nsp_value,
@@ -513,10 +549,10 @@ static void dump_notes(size_t nread)
case NOTE_SPINLOCK_UNLOCK:
{
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u unlocking spinlock=%p
value=%u "
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u unlocking spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
spinlock,
(unsigned int)note_spinlock->nsp_value,
@@ -526,10 +562,10 @@ static void dump_notes(size_t nread)
case NOTE_SPINLOCK_ABORT:
{
- syslog(LOG_INFO,
- "%08lx: Task %u CPU%u abort wait on spinlock=%p
value=%u "
+ syslog_time(LOG_INFO,
+ "Task %u CPU%u abort wait on spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
(unsigned int)note->nc_cpu,
spinlock,
(unsigned int)note_spinlock->nsp_value,
@@ -539,10 +575,10 @@ static void dump_notes(size_t nread)
#else
case NOTE_SPINLOCK_LOCK:
{
- syslog(LOG_INFO,
- "%08lx: Task %u wait for spinlock=%p value=%u "
+ syslog_time(LOG_INFO,
+ "Task %u wait for spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
spinlock,
(unsigned int)note_spinlock->nsp_value,
(unsigned int)note->nc_priority);
@@ -551,9 +587,9 @@ static void dump_notes(size_t nread)
case NOTE_SPINLOCK_LOCKED:
{
- syslog(LOG_INFO,
- "%08lx: Task %u has spinlock=%p value=%u priority
%u\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u has spinlock=%p value=%u priority %u\n",
+ (unsigned int)pid,
spinlock,
(unsigned int)note_spinlock->nsp_value,
(unsigned int)note->nc_priority);
@@ -562,10 +598,10 @@ static void dump_notes(size_t nread)
case NOTE_SPINLOCK_UNLOCK:
{
- syslog(LOG_INFO,
- "%08lx: Task %u unlocking spinlock=%p value=%u "
+ syslog_time(LOG_INFO,
+ "Task %u unlocking spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
spinlock,
(unsigned int)note_spinlock->nsp_value,
(unsigned int)note->nc_priority);
@@ -574,10 +610,10 @@ static void dump_notes(size_t nread)
case NOTE_SPINLOCK_ABORT:
{
- syslog(LOG_INFO,
- "%08lx: Task %u abort wait on spinlock=%p value=%u "
+ syslog_time(LOG_INFO,
+ "Task %u abort wait on spinlock=%p value=%u "
"priority %u\n",
- (unsigned long)systime, (unsigned int)pid,
+ (unsigned int)pid,
spinlock,
(unsigned int)note_spinlock->nsp_value,
(unsigned int)note->nc_priority);
@@ -603,9 +639,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u Enter SYSCALL %d\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u Enter SYSCALL %d\n",
+ (unsigned int)pid,
note_sysenter->nsc_nr);
}
break;
@@ -638,9 +674,9 @@ static void dump_notes(size_t nread)
#endif
;
- syslog(LOG_INFO,
- "%08lx: Task %u Leave SYSCALL %d: %" PRIdPTR "\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u Leave SYSCALL %d: %" PRIdPTR "\n",
+ (unsigned int)pid,
note_sysleave->nsc_nr, result);
}
break;
@@ -661,9 +697,9 @@ static void dump_notes(size_t nread)
return;
}
- syslog(LOG_INFO,
- "%08lx: Task %u %s IRQ %d\n",
- (unsigned long)systime, (unsigned int)pid,
+ syslog_time(LOG_INFO,
+ "Task %u %s IRQ %d\n",
+ (unsigned int)pid,
note->nc_type == NOTE_IRQ_ENTER ? "Enter" : "Leave",
note_irq->nih_irq);
}
diff --git a/system/trace/trace_dump.c b/system/trace/trace_dump.c
index edaf77a..380b139 100644
--- a/system/trace/trace_dump.c
+++ b/system/trace/trace_dump.c
@@ -254,10 +254,21 @@ static void trace_dump_header(FAR FILE *out,
FAR struct trace_dump_context_s *ctx)
{
pid_t pid;
+#ifdef CONFIG_SCHED_INSTRUMENTATION_HIRES
+ uint32_t nsec = note->nc_systime_nsec[0] +
+ (note->nc_systime_nsec[1] << 8) +
+ (note->nc_systime_nsec[2] << 16) +
+ (note->nc_systime_nsec[3] << 24);
+ uint32_t sec = note->nc_systime_sec[0] +
+ (note->nc_systime_sec[1] << 8) +
+ (note->nc_systime_sec[2] << 16) +
+ (note->nc_systime_sec[3] << 24);
+#else
uint32_t systime = note->nc_systime[0] +
(note->nc_systime[1] << 8) +
(note->nc_systime[2] << 16) +
(note->nc_systime[3] << 24);
+#endif
#ifdef CONFIG_SMP
int cpu = note->nc_cpu;
#else
@@ -268,9 +279,14 @@ static void trace_dump_header(FAR FILE *out,
fprintf(out, "%8s-%-3u [%d] %3u.%09u: ",
get_task_name(pid, ctx), get_pid(pid), cpu,
+#ifdef CONFIG_SCHED_INSTRUMENTATION_HIRES
+ sec, nsec
+#else
systime / (1000 * 1000 / CONFIG_USEC_PER_TICK),
(systime % (1000 * 1000 / CONFIG_USEC_PER_TICK))
- * CONFIG_USEC_PER_TICK * 1000);
+ * CONFIG_USEC_PER_TICK * 1000
+#endif
+ );
}
/****************************************************************************
