Date: Sun, 31 Dec 2017 09:24:41 +0000 (UTC) From: Colin Percival <cperciva@FreeBSD.org> To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r327432 - in head/sys: arm/amlogic/aml8726 arm/arm arm/at91 arm/cavium/cns11xx arm/lpc arm/mv arm/ralink arm/xscale/i8134x arm/xscale/ixp425 arm/xscale/pxa kern mips/ingenic mips/mips m... Message-ID: <201712310924.vBV9OfmJ047059@repo.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: cperciva Date: Sun Dec 31 09:24:41 2017 New Revision: 327432 URL: https://svnweb.freebsd.org/changeset/base/327432 Log: Use the TSLOG framework to record entry/exit timestamps for DELAY and _vprintf; these functions are called in many places and can contribute meaningfully to the total time spent booting. Modified: head/sys/arm/amlogic/aml8726/aml8726_timer.c head/sys/arm/arm/generic_timer.c head/sys/arm/arm/machdep.c head/sys/arm/arm/mpcore_timer.c head/sys/arm/at91/at91_machdep.c head/sys/arm/cavium/cns11xx/timer.c head/sys/arm/lpc/lpc_timer.c head/sys/arm/mv/timer.c head/sys/arm/ralink/rt1310_timer.c head/sys/arm/xscale/i8134x/i80321_timer.c head/sys/arm/xscale/ixp425/ixp425_timer.c head/sys/arm/xscale/pxa/pxa_timer.c head/sys/kern/subr_prf.c head/sys/mips/ingenic/jz4780_timer.c head/sys/mips/mips/tick.c head/sys/mips/nlm/tick.c head/sys/mips/rmi/tick.c head/sys/powerpc/powerpc/clock.c head/sys/riscv/riscv/timer.c head/sys/sparc64/sparc64/clock.c head/sys/x86/x86/delay.c Modified: head/sys/arm/amlogic/aml8726/aml8726_timer.c ============================================================================== --- head/sys/arm/amlogic/aml8726/aml8726_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/amlogic/aml8726/aml8726_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -347,6 +347,7 @@ DELAY(int usec) } return; } + TSENTER(); /* * Some of the other timers in the source tree do this calculation as: @@ -391,4 +392,5 @@ DELAY(int usec) previous = now; remaining -= delta; } + TSEXIT(); } Modified: head/sys/arm/arm/generic_timer.c ============================================================================== --- head/sys/arm/arm/generic_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/arm/generic_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -526,6 +526,7 @@ DELAY(int usec) { int32_t counts; + TSENTER(); /* * Check the timers are setup, if not just * use a for loop for the meantime @@ -540,6 +541,7 @@ DELAY(int usec) cpufunc_nullop(); } else arm_tmr_do_delay(usec, arm_tmr_sc); + TSEXIT(); } #endif Modified: head/sys/arm/arm/machdep.c ============================================================================== --- head/sys/arm/arm/machdep.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/arm/machdep.c Sun Dec 31 09:24:41 2017 (r327432) @@ -347,7 +347,9 @@ void DELAY(int usec) { + TSENTER(); delay_impl(usec, delay_arg); + TSEXIT(); } #endif Modified: head/sys/arm/arm/mpcore_timer.c ============================================================================== --- head/sys/arm/arm/mpcore_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/arm/mpcore_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -547,6 +547,7 @@ DELAY(int usec) struct arm_tmr_softc *sc; int32_t counts; + TSENTER(); /* Check the timers are setup, if not just use a for loop for the meantime */ if (arm_tmr_tc == NULL || arm_tmr_timecount.tc_frequency == 0) { for (; usec > 0; usec--) @@ -558,5 +559,6 @@ DELAY(int usec) sc = arm_tmr_tc->tc_priv; arm_tmr_delay(usec, sc); } + TSEXIT(); } #endif Modified: head/sys/arm/at91/at91_machdep.c ============================================================================== --- head/sys/arm/at91/at91_machdep.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/at91/at91_machdep.c Sun Dec 31 09:24:41 2017 (r327432) @@ -672,8 +672,10 @@ void DELAY(int n) { + TSENTER(); if (soc_info.soc_data) soc_info.soc_data->soc_delay(n); + TSEXIT(); } void Modified: head/sys/arm/cavium/cns11xx/timer.c ============================================================================== --- head/sys/arm/cavium/cns11xx/timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/cavium/cns11xx/timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -122,6 +122,7 @@ DELAY(int usec) ; return; } + TSENTER(); val = read_timer_counter_noint(); nticks = (((APB_clock / 1000) * usec) / 1000) + 100; @@ -135,7 +136,7 @@ DELAY(int usec) val = val_temp; } - + TSEXIT(); } /* Modified: head/sys/arm/lpc/lpc_timer.c ============================================================================== --- head/sys/arm/lpc/lpc_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/lpc/lpc_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -292,6 +292,7 @@ DELAY(int usec) ; return; } + TSENTER(); first = lpc_get_timecount(&lpc_timecounter); while (val > 0) { @@ -304,4 +305,5 @@ DELAY(int usec) val -= (last - first); first = last; } + TSEXIT(); } Modified: head/sys/arm/mv/timer.c ============================================================================== --- head/sys/arm/mv/timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/mv/timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -272,6 +272,7 @@ DELAY(int usec) __asm __volatile("nop" ::: "memory"); return; } + TSENTER(); val = mv_get_timer(1); nticks = ((MV_CLOCK_SRC / 1000000 + 1) * usec); @@ -285,6 +286,7 @@ DELAY(int usec) val = val_temp; } + TSEXIT(); } static uint32_t Modified: head/sys/arm/ralink/rt1310_timer.c ============================================================================== --- head/sys/arm/ralink/rt1310_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/ralink/rt1310_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -326,6 +326,7 @@ DELAY(int usec) ; return; } + TSENTER(); first = rt1310_get_timecount(&rt1310_timecounter); while (val > 0) { @@ -338,4 +339,5 @@ DELAY(int usec) val -= (last - first); first = last; } + TSEXIT(); } Modified: head/sys/arm/xscale/i8134x/i80321_timer.c ============================================================================== --- head/sys/arm/xscale/i8134x/i80321_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/xscale/i8134x/i80321_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -428,6 +428,7 @@ DELAY(int n) { uint32_t cur, last, delta, usecs; + TSENTER(); /* * This works by polling the timer and counting the * number of microseconds that go by. @@ -451,6 +452,7 @@ DELAY(int n) delta %= COUNTS_PER_USEC; } } + TSEXIT(); } /* Modified: head/sys/arm/xscale/ixp425/ixp425_timer.c ============================================================================== --- head/sys/arm/xscale/ixp425/ixp425_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/xscale/ixp425/ixp425_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -213,6 +213,7 @@ DELAY(int n) if (n == 0) return; + TSENTER(); /* * Clamp the timeout at a maximum value (about 32 seconds with @@ -233,6 +234,7 @@ DELAY(int n) usecs -= (int)(last - first); first = last; } + TSEXIT(); } /* Modified: head/sys/arm/xscale/pxa/pxa_timer.c ============================================================================== --- head/sys/arm/xscale/pxa/pxa_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/arm/xscale/pxa/pxa_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -214,10 +214,12 @@ DELAY(int usec) ; return; } + TSENTER(); val = pxa_timer_get_oscr(); val += (PXA_TIMER_FREQUENCY * usec) / 1000000; while (pxa_timer_get_oscr() <= val); + TSEXIT(); } uint32_t Modified: head/sys/kern/subr_prf.c ============================================================================== --- head/sys/kern/subr_prf.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/kern/subr_prf.c Sun Dec 31 09:24:41 2017 (r327432) @@ -276,6 +276,7 @@ _vprintf(int level, int flags, const char *fmt, va_lis char bufr[PRINTF_BUFR_SIZE]; #endif + TSENTER(); pca.tty = NULL; pca.pri = level; pca.flags = flags; @@ -303,6 +304,7 @@ _vprintf(int level, int flags, const char *fmt, va_lis } #endif + TSEXIT(); return (retval); } Modified: head/sys/mips/ingenic/jz4780_timer.c ============================================================================== --- head/sys/mips/ingenic/jz4780_timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/mips/ingenic/jz4780_timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -283,6 +283,7 @@ DELAY(int usec) } return; } + TSENTER(); /* * Some of the other timers in the source tree do this calculation as: @@ -327,6 +328,7 @@ DELAY(int usec) previous = now; remaining -= delta; } + TSEXIT(); } void Modified: head/sys/mips/mips/tick.c ============================================================================== --- head/sys/mips/mips/tick.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/mips/mips/tick.c Sun Dec 31 09:24:41 2017 (r327432) @@ -197,6 +197,7 @@ DELAY(int n) { uint32_t cur, last, delta, usecs; + TSENTER(); /* * This works by polling the timer and counting the number of * microseconds that go by. @@ -220,6 +221,7 @@ DELAY(int n) delta %= cycles_per_usec; } } + TSEXIT(); } static int Modified: head/sys/mips/nlm/tick.c ============================================================================== --- head/sys/mips/nlm/tick.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/mips/nlm/tick.c Sun Dec 31 09:24:41 2017 (r327432) @@ -198,6 +198,7 @@ DELAY(int n) { uint32_t cur, last, delta, usecs; + TSENTER(); /* * This works by polling the timer and counting the number of * microseconds that go by. @@ -221,6 +222,7 @@ DELAY(int n) delta %= cycles_per_usec; } } + TSEXIT(); } static int Modified: head/sys/mips/rmi/tick.c ============================================================================== --- head/sys/mips/rmi/tick.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/mips/rmi/tick.c Sun Dec 31 09:24:41 2017 (r327432) @@ -195,6 +195,7 @@ DELAY(int n) { uint32_t cur, last, delta, usecs; + TSENTER(); /* * This works by polling the timer and counting the number of * microseconds that go by. @@ -218,6 +219,7 @@ DELAY(int n) delta %= cycles_per_usec; } } + TSEXIT(); } static int Modified: head/sys/powerpc/powerpc/clock.c ============================================================================== --- head/sys/powerpc/powerpc/clock.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/powerpc/powerpc/clock.c Sun Dec 31 09:24:41 2017 (r327432) @@ -305,9 +305,11 @@ DELAY(int n) { u_quad_t tb, ttb; + TSENTER(); tb = mftb(); ttb = tb + howmany(n * 1000, ns_per_tick); while (tb < ttb) tb = mftb(); + TSEXIT(); } Modified: head/sys/riscv/riscv/timer.c ============================================================================== --- head/sys/riscv/riscv/timer.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/riscv/riscv/timer.c Sun Dec 31 09:24:41 2017 (r327432) @@ -261,6 +261,7 @@ DELAY(int usec) cpufunc_nullop(); return; } + TSENTER(); /* Get the number of times to count */ counts_per_usec = ((riscv_timer_timecount.tc_frequency / 1000000) + 1); @@ -283,4 +284,5 @@ DELAY(int usec) counts -= (int64_t)(last - first); first = last; } + TSEXIT(); } Modified: head/sys/sparc64/sparc64/clock.c ============================================================================== --- head/sys/sparc64/sparc64/clock.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/sparc64/sparc64/clock.c Sun Dec 31 09:24:41 2017 (r327432) @@ -45,6 +45,7 @@ DELAY(int usec) if (usec < 0) return; + TSENTER(); /* * We avoid being migrated to another CPU with a possibly @@ -57,5 +58,6 @@ DELAY(int usec) cpu_spinwait(); sched_unpin(); + TSEXIT(); } Modified: head/sys/x86/x86/delay.c ============================================================================== --- head/sys/x86/x86/delay.c Sun Dec 31 09:24:11 2017 (r327431) +++ head/sys/x86/x86/delay.c Sun Dec 31 09:24:41 2017 (r327432) @@ -101,8 +101,12 @@ void DELAY(int n) { - if (delay_tc(n)) + TSENTER(); + if (delay_tc(n)) { + TSEXIT(); return; + } init_ops.early_delay(n); + TSEXIT(); }
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201712310924.vBV9OfmJ047059>