Date: Fri, 1 Mar 2013 02:59:56 +0000 (UTC) From: Alexander Motin <mav@FreeBSD.org> To: src-committers@freebsd.org, svn-src-projects@freebsd.org Subject: svn commit: r247524 - projects/calloutng/sys/kern Message-ID: <201303010259.r212xuFS057779@svn.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: mav Date: Fri Mar 1 02:59:56 2013 New Revision: 247524 URL: http://svnweb.freebsd.org/changeset/base/247524 Log: Add statistics to better diagnose and tune callout subsystem parameters. Setting kern.callout_stat sysctl dumps to console statistics for callouts scheduled at that moment alike to this: Scheduled callouts statistic snapshot: Callouts: 69 Buckets/CPU: 32768 Bucket size: 0.000976s C/Bk: med 0 avg 0.000526 max 10 Time: med 1.000000s avg 1580.594786s max 84945.674598s Prec: med 0.250000s avg 106.280672s max 5379.937129s Distribution: buckets time tcum prec pcum 0.007812s 2**3 0 0 2 2 0.015625s 2**4 0 0 2 4 0.031250s 2**5 13 13 3 7 0.062500s 2**6 2 15 15 22 0.125000s 2**7 4 19 1 23 0.250000s 2**8 1 20 13 36 0.500000s 2**9 11 31 11 47 1.000000s 2**10 8 39 1 48 2.000000s 2**11 4 43 3 51 4.000000s 2**12 3 46 4 55 8.000000s 2**13 5 51 1 56 16.000000s 2**14 0 51 2 58 32.000000s 2**15 3 54 1 59 64.000000s 2**16 4 58 2 61 128.000000s 2**17 1 59 3 64 256.000000s 2**18 0 59 2 66 512.000000s 2**19 1 60 2 68 1024.000000s 2**20 4 64 0 68 2048.000000s 2**21 2 66 0 68 4096.000000s 2**22 0 66 1 69 8192.000000s 2**23 2 68 0 69 65536.000000s 2**26 1 69 0 69 It would be very interesting to analyze such dumps from systems with heavy load of different kinds to see how well callout subsystem is tuned for them by default. Modified: projects/calloutng/sys/kern/kern_timeout.c Modified: projects/calloutng/sys/kern/kern_timeout.c ============================================================================== --- projects/calloutng/sys/kern/kern_timeout.c Fri Mar 1 02:26:28 2013 (r247523) +++ projects/calloutng/sys/kern/kern_timeout.c Fri Mar 1 02:59:56 2013 (r247524) @@ -1307,3 +1307,121 @@ adjust_timeout_calltodo(time_change) return; } #endif /* APM_FIXUP_CALLTODO */ + +static int +flssbt(sbintime_t sbt) +{ + + sbt += (uint64_t)sbt >> 1; + if (sizeof(long) >= sizeof(sbintime_t)) + return (flsl(sbt)); + if (sbt >= SBT_1S) + return (flsl(((uint64_t)sbt) >> 32) + 32); + return (flsl(sbt)); +} + +/* + * Dump immediate statistic snapshot of the scheduled callouts. + */ +static int +sysctl_kern_callout_stat(SYSCTL_HANDLER_ARGS) +{ + struct callout *tmp; + struct callout_cpu *cc; + struct callout_tailq *sc; + sbintime_t maxpr, maxt, medpr, medt, now, spr, st, t; + int ct[64], cpr[64], ccpbk[32]; + int error, val, i, count, tcum, pcum, maxc, c, medc; +#ifdef SMP + int cpu; +#endif + + val = 0; + error = sysctl_handle_int(oidp, &val, 0, req); + if (error != 0 || req->newptr == NULL) + return (error); + count = maxc = 0; + st = spr = maxt = maxpr = 0; + bzero(ccpbk, sizeof(ccpbk)); + bzero(ct, sizeof(ct)); + bzero(cpr, sizeof(cpr)); + now = sbinuptime(); +#ifdef SMP + CPU_FOREACH(cpu) { + cc = CC_CPU(cpu); +#else + cc = CC_CPU(timeout_cpu); +#endif + CC_LOCK(cc); + for (i = 0; i < callwheelsize; i++) { + sc = &cc->cc_callwheel[i]; + c = 0; + TAILQ_FOREACH(tmp, sc, c_links.tqe) { + c++; + t = tmp->c_time - now; + if (t < 0) + t = 0; + st += t / SBT_1US; + spr += tmp->c_precision / SBT_1US; + if (t > maxt) + maxt = t; + if (tmp->c_precision > maxpr) + maxpr = tmp->c_precision; + ct[flssbt(t)]++; + cpr[flssbt(tmp->c_precision)]++; + } + if (c > maxc) + maxc = c; + ccpbk[fls(c + c / 2)]++; + count += c; + } + CC_UNLOCK(cc); +#ifdef SMP + } +#endif + + for (i = 0, tcum = 0; i < 64 && tcum < count / 2; i++) + tcum += ct[i]; + medt = (i >= 2) ? (((sbintime_t)1) << (i - 2)) : 0; + for (i = 0, pcum = 0; i < 64 && pcum < count / 2; i++) + pcum += cpr[i]; + medpr = (i >= 2) ? (((sbintime_t)1) << (i - 2)) : 0; + for (i = 0, c = 0; i < 32 && c < count / 2; i++) + c += ccpbk[i]; + medc = (i >= 2) ? (1 << (i - 2)) : 0; + + printf("Scheduled callouts statistic snapshot:\n"); + printf(" Callouts: %6d Buckets/CPU: %6d Bucket size: 0.%06ds\n", + count, callwheelsize, 1000000 >> CC_HASH_SHIFT); + printf(" C/Bk: med %5d avg %6d.%06jd max %6d\n", + medc, + count / callwheelsize / mp_ncpus, + (uint64_t)count * 1000000 / callwheelsize / mp_ncpus % 1000000, + maxc); + printf(" Time: med %5jd.%06jds avg %6jd.%06jds max %6jd.%06jds\n", + medt / SBT_1S, (medt & 0xffffffff) * 1000000 >> 32, + (st / count) / 1000000, (st / count) % 1000000, + maxt / SBT_1S, (maxt & 0xffffffff) * 1000000 >> 32); + printf(" Prec: med %5jd.%06jds avg %6jd.%06jds max %6jd.%06jds\n", + medpr / SBT_1S, (medpr & 0xffffffff) * 1000000 >> 32, + (spr / count) / 1000000, (spr / count) % 1000000, + maxpr / SBT_1S, (maxpr & 0xffffffff) * 1000000 >> 32); + printf(" Distribution: \tbuckets\t time\t tcum\t" + " prec\t pcum\n"); + for (i = 0, tcum = pcum = 0; i < 64; i++) { + if (ct[i] == 0 && cpr[i] == 0) + continue; + t = (i != 0) ? (((sbintime_t)1) << (i - 1)) : 0; + tcum += ct[i]; + pcum += cpr[i]; + printf(" %10jd.%06jds\t 2**%d\t%7d\t%7d\t%7d\t%7d\n", + t / SBT_1S, (t & 0xffffffff) * 1000000 >> 32, + i - 1 - (32 - CC_HASH_SHIFT), + ct[i], tcum, cpr[i], pcum); + } + return (error); +} +SYSCTL_PROC(_kern, OID_AUTO, callout_stat, + CTLTYPE_INT | CTLFLAG_RW | CTLFLAG_MPSAFE, + 0, 0, sysctl_kern_callout_stat, "I", + "Dump immediate statistic snapshot of the scheduled callouts");
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201303010259.r212xuFS057779>