[threadpool-ms] Add tracing

diff --git a/mono/metadata/threadpool-ms.c b/mono/metadata/threadpool-ms.c
index abb293f73c0bf12e2a4dce76a9aabcec90815423..b33f59bfe9850ecb34c6bb96feb25160aaee2cf3 100644 (file)
--- a/mono/metadata/threadpool-ms.c
+++ b/mono/metadata/threadpool-ms.c
@@ -35,6 +35,8 @@
 #include <mono/utils/atomic.h>
 #include <mono/utils/mono-compiler.h>
 #include <mono/utils/mono-complex.h>
+#include <mono/utils/mono-logger.h>
+#include <mono/utils/mono-logger-internal.h>
 #include <mono/utils/mono-proclib.h>
 #include <mono/utils/mono-threads.h>
 #include <mono/utils/mono-time.h>
@@ -514,6 +516,8 @@ worker_park (void)
        mono_cond_t cond;
        MonoInternalThread *thread = mono_thread_internal_current ();
 
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] current worker parking", GetCurrentThreadId ());
+
        mono_cond_init (&cond, NULL);
 
        mono_gc_set_skip_thread (TRUE);
@@ -535,6 +539,8 @@ worker_park (void)
        mono_gc_set_skip_thread (FALSE);
 
        mono_cond_destroy (&cond);
+
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] current worker unparking", GetCurrentThreadId ());
 }
 
 static gboolean
@@ -543,6 +549,8 @@ worker_try_unpark (void)
        gboolean res = FALSE;
        guint len;
 
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] try unpark worker", GetCurrentThreadId ());
+
        mono_mutex_lock (&threadpool->active_threads_lock);
        len = threadpool->parked_threads->len;
        if (len > 0) {
@@ -551,6 +559,9 @@ worker_try_unpark (void)
                res = TRUE;
        }
        mono_mutex_unlock (&threadpool->active_threads_lock);
+
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] try unpark worker, success? %s", GetCurrentThreadId (), res ? "yes" : "no");
+
        return res;
 }
 
@@ -577,6 +588,8 @@ worker_thread (gpointer data)
        ThreadPoolCounter counter;
        gboolean retire = FALSE;
 
+       mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_THREADPOOL, "[%p] worker starting", GetCurrentThreadId ());
+
        g_assert (status >= STATUS_INITIALIZED);
        g_assert (threadpool);
 
@@ -626,6 +639,9 @@ worker_thread (gpointer data)
                tpdomain->outstanding_request --;
                g_assert (tpdomain->outstanding_request >= 0);
 
+               mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] worker running in domain %p",
+                       GetCurrentThreadId (), tpdomain->domain, tpdomain->outstanding_request);
+
                g_assert (tpdomain->domain);
                g_assert (tpdomain->domain->threadpool_jobs >= 0);
                tpdomain->domain->threadpool_jobs ++;
@@ -676,12 +692,17 @@ worker_thread (gpointer data)
                counter._.working--;
                counter._.active --;
        });
+
+       mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_THREADPOOL, "[%p] worker finishing", GetCurrentThreadId ());
 }
 
 static gboolean
 worker_try_create (void)
 {
        ThreadPoolCounter counter;
+       MonoInternalThread *thread;
+
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] try create worker", GetCurrentThreadId ());
 
        COUNTER_ATOMIC (counter, {
                if (counter._.working >= counter._.max_working)
@@ -690,8 +711,13 @@ worker_try_create (void)
                counter._.active ++;
        });
 
-       if (mono_thread_create_internal (mono_get_root_domain (), worker_thread, NULL, TRUE, 0) != NULL)
+       if ((thread = mono_thread_create_internal (mono_get_root_domain (), worker_thread, NULL, TRUE, 0)) != NULL) {
+               mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] try create worker, created %p",
+                       GetCurrentThreadId (), thread->tid);
                return TRUE;
+       }
+
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] try create worker, failed", GetCurrentThreadId ());
 
        COUNTER_ATOMIC (counter, {
                counter._.working --;
@@ -726,6 +752,9 @@ worker_request (MonoDomain *domain)
        g_assert (tpdomain);
        tpdomain->outstanding_request ++;
 
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] request worker, domain = %p, outstanding_request = %d",
+               GetCurrentThreadId (), tpdomain->domain, tpdomain->outstanding_request);
+
        mono_mutex_unlock (&threadpool->domains_lock);
 
        if (threadpool->suspended)
@@ -733,12 +762,17 @@ worker_request (MonoDomain *domain)
 
        monitor_ensure_running ();
 
-       if (worker_try_unpark ())
+       if (worker_try_unpark ()) {
+               mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] request worker, unparked", GetCurrentThreadId ());
                return TRUE;
+       }
 
-       if (worker_try_create ())
+       if (worker_try_create ()) {
+               mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] request worker, created", GetCurrentThreadId ());
                return TRUE;
+       }
 
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] request worker, failed", GetCurrentThreadId ());
        return FALSE;
 }
 
@@ -787,6 +821,8 @@ monitor_thread (void)
 
        mono_cpu_usage (threadpool->cpu_usage_state);
 
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] monitor thread, started", GetCurrentThreadId ());
+
        do {
                MonoInternalThread *thread;
                gboolean all_waitsleepjoin = TRUE;
@@ -845,14 +881,20 @@ monitor_thread (void)
                                if (mono_runtime_is_shutting_down ())
                                        break;
 
-                               if (worker_try_unpark ())
+                               if (worker_try_unpark ()) {
+                                       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] monitor thread, unparked", GetCurrentThreadId ());
                                        break;
+                               }
 
-                               if (worker_try_create ())
+                               if (worker_try_create ()) {
+                                       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] monitor thread, created", GetCurrentThreadId ());
                                        break;
+                               }
                        }
                }
        } while (monitor_should_keep_running ());
+
+       mono_trace (G_LOG_LEVEL_DEBUG, MONO_TRACE_THREADPOOL, "[%p] monitor thread, finished", GetCurrentThreadId ());
 }
 
 static void
@@ -888,6 +930,8 @@ hill_climbing_change_thread_count (gint16 new_thread_count, ThreadPoolHeuristicS
 
        hc = &threadpool->heuristic_hill_climbing;
 
+       mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_THREADPOOL, "[%p] hill climbing, change max number of threads %d", GetCurrentThreadId (), new_thread_count);
+
        hc->last_thread_count = new_thread_count;
        hc->current_sample_interval = rand_next (&hc->random_interval_generator, hc->sample_interval_low, hc->sample_interval_high);
        hc->elapsed_since_last_change = 0;

diff --git a/mono/utils/mono-logger-internal.h b/mono/utils/mono-logger-internal.h
index 93fc010ac93bc2ef52f5ebaf1ce0420b12e12913..209b9e6f0ca0e45437b54ba6373cbda941806d3a 100644 (file)
--- a/mono/utils/mono-logger-internal.h
+++ b/mono/utils/mono-logger-internal.h
@@ -14,13 +14,15 @@ typedef enum {
         MONO_TRACE_CONFIG              = (1<<4),
        MONO_TRACE_AOT                  = (1<<5),
        MONO_TRACE_SECURITY             = (1<<6),
+       MONO_TRACE_THREADPOOL           = (1<<7),
        MONO_TRACE_ALL                  = MONO_TRACE_ASSEMBLY |
                                          MONO_TRACE_TYPE |
                                          MONO_TRACE_DLLIMPORT |
                                          MONO_TRACE_GC |
                                          MONO_TRACE_CONFIG |
                                          MONO_TRACE_AOT |
-                                         MONO_TRACE_SECURITY
+                                         MONO_TRACE_SECURITY |
+                                         MONO_TRACE_THREADPOOL
 } MonoTraceMask;
 
 void 

diff --git a/mono/utils/mono-logger.c b/mono/utils/mono-logger.c
index e5192070fd5e7928073125a20a68e70e9520c9d6..54bf4db6f629e4f8f90f4e0d26ca9136950f2b39 100644 (file)
--- a/mono/utils/mono-logger.c
+++ b/mono/utils/mono-logger.c
@@ -213,10 +213,10 @@ mono_trace_set_mask_string (const char *value)
        const char *tok;
        guint32 flags = 0;
 
-       const char *valid_flags[] = {"asm", "type", "dll", "gc", "cfg", "aot", "security", "all", NULL};
+       const char *valid_flags[] = {"asm", "type", "dll", "gc", "cfg", "aot", "security", "threadpool", "all", NULL};
        const MonoTraceMask     valid_masks[] = {MONO_TRACE_ASSEMBLY, MONO_TRACE_TYPE, MONO_TRACE_DLLIMPORT,
-                                                MONO_TRACE_GC, MONO_TRACE_CONFIG, MONO_TRACE_AOT, MONO_TRACE_SECURITY, 
-                                                MONO_TRACE_ALL };
+                                                MONO_TRACE_GC, MONO_TRACE_CONFIG, MONO_TRACE_AOT, MONO_TRACE_SECURITY,
+                                                MONO_TRACE_THREADPOOL, MONO_TRACE_ALL };
 
        if(!value)
                return;