Source-Changes-HG archive

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]

[src/trunk]: src/sys/kern Switch from ad-hoc logging to dtrace probes.



details:   https://anonhg.NetBSD.org/src/rev/17fa254d5d5a
branches:  trunk
changeset: 1007193:17fa254d5d5a
user:      riastradh <riastradh%NetBSD.org@localhost>
date:      Sun Feb 09 22:57:39 2020 +0000

description:
Switch from ad-hoc logging to dtrace probes.

diffstat:

 sys/kern/kern_threadpool.c |  172 ++++++++++++++++++++++++++++++++------------
 1 files changed, 126 insertions(+), 46 deletions(-)

diffs (truncated from 415 to 300 lines):

diff -r 86d20770133e -r 17fa254d5d5a sys/kern/kern_threadpool.c
--- a/sys/kern/kern_threadpool.c        Sun Feb 09 22:57:26 2020 +0000
+++ b/sys/kern/kern_threadpool.c        Sun Feb 09 22:57:39 2020 +0000
@@ -1,4 +1,4 @@
-/*     $NetBSD: kern_threadpool.c,v 1.16 2020/02/09 22:57:26 riastradh Exp $   */
+/*     $NetBSD: kern_threadpool.c,v 1.17 2020/02/09 22:57:39 riastradh Exp $   */
 
 /*-
  * Copyright (c) 2014, 2018 The NetBSD Foundation, Inc.
@@ -81,7 +81,7 @@
  */
 
 #include <sys/cdefs.h>
-__KERNEL_RCSID(0, "$NetBSD: kern_threadpool.c,v 1.16 2020/02/09 22:57:26 riastradh Exp $");
+__KERNEL_RCSID(0, "$NetBSD: kern_threadpool.c,v 1.17 2020/02/09 22:57:39 riastradh Exp $");
 
 #include <sys/types.h>
 #include <sys/param.h>
@@ -97,10 +97,82 @@
 #include <sys/pool.h>
 #include <sys/proc.h>
 #include <sys/queue.h>
-#include <sys/systm.h>
+#include <sys/sdt.h>
 #include <sys/sysctl.h>
+#include <sys/systm.h>
 #include <sys/threadpool.h>
 
+/* Probes */
+
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, get,
+    "pri_t"/*pri*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, get__create,
+    "pri_t"/*pri*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, get__race,
+    "pri_t"/*pri*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, put,
+    "struct threadpool *"/*pool*/, "pri_t"/*pri*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, put__destroy,
+    "struct threadpool *"/*pool*/, "pri_t"/*pri*/);
+
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, percpu__get,
+    "pri_t"/*pri*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, percpu__get__create,
+    "pri_t"/*pri*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, percpu__get__race,
+    "pri_t"/*pri*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, percpu__put,
+    "struct threadpool *"/*pool*/, "pri_t"/*pri*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, percpu__put__destroy,
+    "struct threadpool *"/*pool*/, "pri_t"/*pri*/);
+
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, create,
+    "struct cpu_info *"/*ci*/, "pri_t"/*pri*/);
+SDT_PROBE_DEFINE3(sdt, kernel, threadpool, create__success,
+    "struct cpu_info *"/*ci*/, "pri_t"/*pri*/, "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE3(sdt, kernel, threadpool, create__failure,
+    "struct cpu_info *"/*ci*/, "pri_t"/*pri*/, "int"/*error*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, destroy,
+    "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, destroy__wait,
+    "struct threadpool *"/*pool*/, "uint64_t"/*refcnt*/);
+
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, schedule__job,
+    "struct threadpool *"/*pool*/, "struct threadpool_job *"/*job*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, schedule__job__running,
+    "struct threadpool *"/*pool*/, "struct threadpool_job *"/*job*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, schedule__job__overseer,
+    "struct threadpool *"/*pool*/, "struct threadpool_job *"/*job*/);
+SDT_PROBE_DEFINE3(sdt, kernel, threadpool, schedule__job__thread,
+    "struct threadpool *"/*pool*/,
+    "struct threadpool_job *"/*job*/,
+    "struct lwp *"/*thread*/);
+
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, overseer__start,
+    "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, overseer__dying,
+    "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, overseer__spawn,
+    "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, overseer__race,
+    "struct threadpool *"/*pool*/,
+    "struct threadpool_job *"/*job*/);
+SDT_PROBE_DEFINE3(sdt, kernel, threadpool, overseer__assign,
+    "struct threadpool *"/*pool*/,
+    "struct threadpool_job *"/*job*/,
+    "struct lwp *"/*thread*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, overseer__exit,
+    "struct threadpool *"/*pool*/);
+
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, thread__start,
+    "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, thread__dying,
+    "struct threadpool *"/*pool*/);
+SDT_PROBE_DEFINE2(sdt, kernel, threadpool, thread__job,
+    "struct threadpool *"/*pool*/, "struct threadpool_job *"/*job*/);
+SDT_PROBE_DEFINE1(sdt, kernel, threadpool, thread__exit,
+    "struct threadpool *"/*pool*/);
+
 /* Data structures */
 
 TAILQ_HEAD(job_head, threadpool_job);
@@ -224,12 +296,6 @@
        LIST_REMOVE(tpp, tpp_link);
 }
 
-#ifdef THREADPOOL_VERBOSE
-#define        TP_LOG(x)               printf x
-#else
-#define        TP_LOG(x)               /* nothing */
-#endif /* THREADPOOL_VERBOSE */
-
 static int
 sysctl_kern_threadpool_idle_ms(SYSCTLFN_ARGS)
 {
@@ -308,6 +374,8 @@
 
        KASSERT(threadpool_pri_is_valid(pri));
 
+       SDT_PROBE2(sdt, kernel, threadpool, create,  ci, pri);
+
        mutex_init(&pool->tp_lock, MUTEX_DEFAULT, IPL_VM);
        /* XXX overseer */
        TAILQ_INIT(&pool->tp_jobs);
@@ -337,6 +405,7 @@
        cv_broadcast(&pool->tp_overseer.tpt_cv);
        mutex_spin_exit(&pool->tp_lock);
 
+       SDT_PROBE3(sdt, kernel, threadpool, create__success,  ci, pri, pool);
        return 0;
 
 fail0: KASSERT(error);
@@ -349,6 +418,7 @@
        KASSERT(!cv_has_waiters(&pool->tp_overseer.tpt_cv));
        cv_destroy(&pool->tp_overseer.tpt_cv);
        mutex_destroy(&pool->tp_lock);
+       SDT_PROBE3(sdt, kernel, threadpool, create__failure,  ci, pri, error);
        return error;
 }
 
@@ -359,6 +429,8 @@
 {
        struct threadpool_thread *thread;
 
+       SDT_PROBE1(sdt, kernel, threadpool, destroy,  pool);
+
        /* Mark the pool dying and wait for threads to commit suicide.  */
        mutex_spin_enter(&pool->tp_lock);
        KASSERT(TAILQ_EMPTY(&pool->tp_jobs));
@@ -367,8 +439,8 @@
        TAILQ_FOREACH(thread, &pool->tp_idle_threads, tpt_entry)
                cv_broadcast(&thread->tpt_cv);
        while (0 < pool->tp_refcnt) {
-               TP_LOG(("%s: draining %" PRIu64 " references...\n", __func__,
-                   pool->tp_refcnt));
+               SDT_PROBE2(sdt, kernel, threadpool, destroy__wait,
+                   pool, pool->tp_refcnt);
                cv_wait(&pool->tp_overseer.tpt_cv, &pool->tp_lock);
        }
        mutex_spin_exit(&pool->tp_lock);
@@ -413,6 +485,8 @@
 
        ASSERT_SLEEPABLE();
 
+       SDT_PROBE1(sdt, kernel, threadpool, get,  pri);
+
        if (! threadpool_pri_is_valid(pri))
                return EINVAL;
 
@@ -420,8 +494,7 @@
        tpu = threadpool_lookup_unbound(pri);
        if (tpu == NULL) {
                mutex_exit(&threadpools_lock);
-               TP_LOG(("%s: No pool for pri=%d, creating one.\n",
-                   __func__, (int)pri));
+               SDT_PROBE1(sdt, kernel, threadpool, get__create,  pri);
                tmp = kmem_zalloc(sizeof(*tmp), KM_SLEEP);
                error = threadpool_create(&tmp->tpu_pool, NULL, pri);
                if (error) {
@@ -431,11 +504,11 @@
                mutex_enter(&threadpools_lock);
                tpu = threadpool_lookup_unbound(pri);
                if (tpu == NULL) {
-                       TP_LOG(("%s: Won the creation race for pri=%d.\n",
-                           __func__, (int)pri));
                        tpu = tmp;
                        tmp = NULL;
                        threadpool_insert_unbound(tpu);
+               } else {
+                       SDT_PROBE1(sdt, kernel, threadpool, get__race,  pri);
                }
        }
        KASSERT(tpu != NULL);
@@ -459,15 +532,15 @@
            container_of(pool, struct threadpool_unbound, tpu_pool);
 
        ASSERT_SLEEPABLE();
+       KASSERT(threadpool_pri_is_valid(pri));
 
-       KASSERT(threadpool_pri_is_valid(pri));
+       SDT_PROBE2(sdt, kernel, threadpool, put,  pool, pri);
 
        mutex_enter(&threadpools_lock);
        KASSERT(tpu == threadpool_lookup_unbound(pri));
        KASSERT(0 < tpu->tpu_refcnt);
        if (--tpu->tpu_refcnt == 0) {
-               TP_LOG(("%s: Last reference for pri=%d, destroying pool.\n",
-                   __func__, (int)pri));
+               SDT_PROBE2(sdt, kernel, threadpool, put__destroy,  pool, pri);
                threadpool_remove_unbound(tpu);
        } else {
                tpu = NULL;
@@ -490,6 +563,8 @@
 
        ASSERT_SLEEPABLE();
 
+       SDT_PROBE1(sdt, kernel, threadpool, percpu__get,  pri);
+
        if (! threadpool_pri_is_valid(pri))
                return EINVAL;
 
@@ -497,8 +572,7 @@
        pool_percpu = threadpool_lookup_percpu(pri);
        if (pool_percpu == NULL) {
                mutex_exit(&threadpools_lock);
-               TP_LOG(("%s: No pool for pri=%d, creating one.\n",
-                   __func__, (int)pri));
+               SDT_PROBE1(sdt, kernel, threadpool, percpu__get__create,  pri);
                error = threadpool_percpu_create(&tmp, pri);
                if (error)
                        return error;
@@ -506,11 +580,12 @@
                mutex_enter(&threadpools_lock);
                pool_percpu = threadpool_lookup_percpu(pri);
                if (pool_percpu == NULL) {
-                       TP_LOG(("%s: Won the creation race for pri=%d.\n",
-                           __func__, (int)pri));
                        pool_percpu = tmp;
                        tmp = NULL;
                        threadpool_insert_percpu(pool_percpu);
+               } else {
+                       SDT_PROBE1(sdt, kernel, threadpool, percpu__get__race,
+                           pri);
                }
        }
        KASSERT(pool_percpu != NULL);
@@ -533,12 +608,14 @@
 
        KASSERT(threadpool_pri_is_valid(pri));
 
+       SDT_PROBE2(sdt, kernel, threadpool, percpu__put,  pool_percpu, pri);
+
        mutex_enter(&threadpools_lock);
        KASSERT(pool_percpu == threadpool_lookup_percpu(pri));
        KASSERT(0 < pool_percpu->tpp_refcnt);
        if (--pool_percpu->tpp_refcnt == 0) {
-               TP_LOG(("%s: Last reference for pri=%d, destroying pool.\n",
-                   __func__, (int)pri));
+               SDT_PROBE2(sdt, kernel, threadpool, percpu__put__destroy,
+                   pool_percpu, pri);
                threadpool_remove_percpu(pool_percpu);
        } else {
                pool_percpu = NULL;
@@ -768,6 +845,8 @@
 
        KASSERT(mutex_owned(job->job_lock));
 
+       SDT_PROBE2(sdt, kernel, threadpool, schedule__job,  pool, job);
+
        /*
         * If the job's already running, let it keep running.  The job
         * is guaranteed by the interlock not to end early -- if it had
@@ -775,8 +854,8 @@
         * to NULL under the interlock.
         */
        if (__predict_true(job->job_thread != NULL)) {
-               TP_LOG(("%s: job '%s' already runnining.\n",
-                   __func__, job->job_name));
+               SDT_PROBE2(sdt, kernel, threadpool, schedule__job__running,
+                   pool, job);
                return;
        }
 
@@ -786,15 +865,15 @@
        mutex_spin_enter(&pool->tp_lock);
        if (__predict_false(TAILQ_EMPTY(&pool->tp_idle_threads))) {
                /* Nobody's idle.  Give it to the overseer.  */
-               TP_LOG(("%s: giving job '%s' to overseer.\n",
-                   __func__, job->job_name));
+               SDT_PROBE2(sdt, kernel, threadpool, schedule__job__overseer,
+                   pool, job);
                job->job_thread = &pool->tp_overseer;
                TAILQ_INSERT_TAIL(&pool->tp_jobs, job, job_entry);
        } else {
                /* Assign it to the first idle thread.  */
                job->job_thread = TAILQ_FIRST(&pool->tp_idle_threads);
-               TP_LOG(("%s: giving job '%s' to idle thread %p.\n",
-                   __func__, job->job_name, job->job_thread));
+               SDT_PROBE3(sdt, kernel, threadpool, schedule__job__thread,
+                   pool, job, job->job_thread->tpt_lwp);



Home | Main Index | Thread Index | Old Index