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 <yuuichi.a.nakam...@sony.com> 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 + ); } /****************************************************************************