From: Julian Seward Date: Fri, 12 Apr 2002 20:12:20 +0000 (+0000) Subject: Clean up debug printing for scheduler / pthreads. Two new flags, X-Git-Tag: svn/VALGRIND_1_0_3~391 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=c59b539faf58ef76cf6abb2caf9d4ad86d14dbac;p=thirdparty%2Fvalgrind.git Clean up debug printing for scheduler / pthreads. Two new flags, --trace-sched=no|yes and --trace-pthread=no|yes, if you really want to see tons of gory details. git-svn-id: svn://svn.valgrind.org/valgrind/trunk@55 --- diff --git a/coregrind/arch/x86-linux/vg_libpthread.c b/coregrind/arch/x86-linux/vg_libpthread.c index e8d60430be..ca2057a2db 100644 --- a/coregrind/arch/x86-linux/vg_libpthread.c +++ b/coregrind/arch/x86-linux/vg_libpthread.c @@ -152,17 +152,17 @@ int* __errno_location ( void ) int pthread_mutexattr_init(pthread_mutexattr_t *attr) { - char* str = "pthread_mutexattr_init\n"; - write(2, str, strlen(str)); - return 0; + char* str = "IGNORED pthread_mutexattr_init\n"; + write(2, str, strlen(str)); + return 0; } int pthread_mutex_init(pthread_mutex_t *mutex, const pthread_mutexattr_t *mutexattr) { int res; - char* str = "pthread_mutex_init\n"; - write(2, str, strlen(str)); + // char* str = "pthread_mutex_init\n"; + // write(2, str, strlen(str)); ensure_valgrind("pthread_mutex_init"); VALGRIND_MAGIC_SEQUENCE(res, 0 /* default */, VG_USERREQ__PTHREAD_MUTEX_INIT, @@ -172,7 +172,7 @@ int pthread_mutex_init(pthread_mutex_t *mutex, int pthread_mutexattr_destroy(pthread_mutexattr_t *attr) { - char* str = "pthread_mutexattr_destroy\n"; + char* str = "IGNORED pthread_mutexattr_destroy\n"; write(2, str, strlen(str)); return 0; } @@ -237,7 +237,7 @@ int pthread_mutex_destroy(pthread_mutex_t *mutex) int pthread_setcanceltype(int type, int *oldtype) { - char* str = "pthread_setcanceltype\n"; + char* str = "IGNORED pthread_setcanceltype\n"; write(2, str, strlen(str)); return 0; } diff --git a/coregrind/valgrind.in b/coregrind/valgrind.in index bc4594004c..35249d9a9e 100755 --- a/coregrind/valgrind.in +++ b/coregrind/valgrind.in @@ -87,6 +87,10 @@ do --trace-symtab=no) vgopts="$vgopts $arg"; shift;; --trace-malloc=yes) vgopts="$vgopts $arg"; shift;; --trace-malloc=no) vgopts="$vgopts $arg"; shift;; + --trace-sched=yes) vgopts="$vgopts $arg"; shift;; + --trace-sched=no) vgopts="$vgopts $arg"; shift;; + --trace-pthread=yes) vgopts="$vgopts $arg"; shift;; + --trace-pthread=no) vgopts="$vgopts $arg"; shift;; --stop-after=*) vgopts="$vgopts $arg"; shift;; --dump-error=*) vgopts="$vgopts $arg"; shift;; -*) dousage=1; break;; @@ -146,6 +150,8 @@ if [ z"$argopts" = z -o z"$dousage" = z1 ]; then echo " --trace-signals=no|yes show signal handling details? [no]" echo " --trace-symtab=no|yes show symbol table details? [no]" echo " --trace-malloc=no|yes show client malloc details? [no]" + echo " --trace-sched=no|yes show thread scheduler details? [no]" + echo " --trace-pthread=no|yes show pthread event details? [no]" echo " --stop-after= switch to real CPU after executing" echo " basic blocks [infinity]" echo " --dump-error= show translation for basic block" diff --git a/coregrind/vg_include.h b/coregrind/vg_include.h index 5d9825f12d..56ee85d13e 100644 --- a/coregrind/vg_include.h +++ b/coregrind/vg_include.h @@ -242,6 +242,10 @@ extern Bool VG_(clo_trace_signals); extern Bool VG_(clo_trace_symtab); /* DEBUG: print malloc details? default: NO */ extern Bool VG_(clo_trace_malloc); +/* DEBUG: print thread scheduling events? default: NO */ +extern Bool VG_(clo_trace_sched); +/* DEBUG: print pthread (mutex etc) events? default: NO */ +extern Bool VG_(clo_trace_pthread); /* Stop after this many basic blocks. default: Infinity. */ extern ULong VG_(clo_stop_after); /* Display gory details for the k'th most popular error. default: diff --git a/coregrind/vg_libpthread.c b/coregrind/vg_libpthread.c index e8d60430be..ca2057a2db 100644 --- a/coregrind/vg_libpthread.c +++ b/coregrind/vg_libpthread.c @@ -152,17 +152,17 @@ int* __errno_location ( void ) int pthread_mutexattr_init(pthread_mutexattr_t *attr) { - char* str = "pthread_mutexattr_init\n"; - write(2, str, strlen(str)); - return 0; + char* str = "IGNORED pthread_mutexattr_init\n"; + write(2, str, strlen(str)); + return 0; } int pthread_mutex_init(pthread_mutex_t *mutex, const pthread_mutexattr_t *mutexattr) { int res; - char* str = "pthread_mutex_init\n"; - write(2, str, strlen(str)); + // char* str = "pthread_mutex_init\n"; + // write(2, str, strlen(str)); ensure_valgrind("pthread_mutex_init"); VALGRIND_MAGIC_SEQUENCE(res, 0 /* default */, VG_USERREQ__PTHREAD_MUTEX_INIT, @@ -172,7 +172,7 @@ int pthread_mutex_init(pthread_mutex_t *mutex, int pthread_mutexattr_destroy(pthread_mutexattr_t *attr) { - char* str = "pthread_mutexattr_destroy\n"; + char* str = "IGNORED pthread_mutexattr_destroy\n"; write(2, str, strlen(str)); return 0; } @@ -237,7 +237,7 @@ int pthread_mutex_destroy(pthread_mutex_t *mutex) int pthread_setcanceltype(int type, int *oldtype) { - char* str = "pthread_setcanceltype\n"; + char* str = "IGNORED pthread_setcanceltype\n"; write(2, str, strlen(str)); return 0; } diff --git a/coregrind/vg_main.c b/coregrind/vg_main.c index 6e5c01ab03..128bfddff3 100644 --- a/coregrind/vg_main.c +++ b/coregrind/vg_main.c @@ -439,6 +439,8 @@ Bool VG_(clo_trace_syscalls); Bool VG_(clo_trace_signals); Bool VG_(clo_trace_symtab); Bool VG_(clo_trace_malloc); +Bool VG_(clo_trace_sched); +Bool VG_(clo_trace_pthread); ULong VG_(clo_stop_after); Int VG_(clo_dump_error); Int VG_(clo_backtrace_size); @@ -521,6 +523,8 @@ static void process_cmd_line_options ( void ) VG_(clo_trace_signals) = False; VG_(clo_trace_symtab) = False; VG_(clo_trace_malloc) = False; + VG_(clo_trace_sched) = False; + VG_(clo_trace_pthread) = False; VG_(clo_stop_after) = 1000000000000LL; VG_(clo_dump_error) = 0; VG_(clo_backtrace_size) = 4; @@ -789,6 +793,16 @@ static void process_cmd_line_options ( void ) else if (STREQ(argv[i], "--trace-malloc=no")) VG_(clo_trace_malloc) = False; + else if (STREQ(argv[i], "--trace-sched=yes")) + VG_(clo_trace_sched) = True; + else if (STREQ(argv[i], "--trace-sched=no")) + VG_(clo_trace_sched) = False; + + else if (STREQ(argv[i], "--trace-pthread=yes")) + VG_(clo_trace_pthread) = True; + else if (STREQ(argv[i], "--trace-pthread=no")) + VG_(clo_trace_pthread) = False; + else if (STREQN(13, argv[i], "--stop-after=")) VG_(clo_stop_after) = VG_(atoll)(&argv[i][13]); diff --git a/coregrind/vg_scheduler.c b/coregrind/vg_scheduler.c index c1a26ad2c9..f75fcce8a6 100644 --- a/coregrind/vg_scheduler.c +++ b/coregrind/vg_scheduler.c @@ -50,7 +50,11 @@ anyone at all! - return bogus RA: %EAX trashed, so pthread_joiner gets nonsense exit codes -- when a thread is done mark its stack as noaccess */ +- when a thread is done mark its stack as noaccess + +- make signal return and .fini call be detected via request mechanism + + */ /* --------------------------------------------------------------------- @@ -166,8 +170,14 @@ void add_waiting_fd ( ThreadId tid, Int fd, Int syscall_no ) static void print_sched_event ( ThreadId tid, Char* what ) { - if (1) - VG_(message)(Vg_DebugMsg, "SCHED[%d]: %s", tid, what ); + VG_(message)(Vg_DebugMsg, "SCHED[%d]: %s", tid, what ); +} + + +static +void print_pthread_event ( ThreadId tid, Char* what ) +{ + VG_(message)(Vg_DebugMsg, "PTHREAD[%d]: %s", tid, what ); } @@ -566,7 +576,7 @@ void sched_do_syscall ( ThreadId tid ) + (ULong)( (UInt)(req->tv_nsec) / 1000 ); vg_threads[tid].status = VgTs_Sleeping; vg_threads[tid].awaken_at = t_awaken; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "at %lu: nanosleep for %lu", t_now, t_awaken-t_now); print_sched_event(tid, msg_buf); @@ -642,7 +652,7 @@ void sched_do_syscall ( ThreadId tid ) add_waiting_fd(tid, fd, saved_eax /* which holds the syscall # */); /* Deschedule thread until an I/O completion happens. */ vg_threads[tid].status = VgTs_WaitFD; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf,"block until I/O ready on fd %d", fd); print_sched_event(tid, msg_buf); } @@ -702,7 +712,7 @@ void poll_for_ready_fds ( void ) vg_threads[tid].m_eax = 0; /* Reschedule this thread. */ vg_threads[tid].status = VgTs_Runnable; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "at %lu: nanosleep done", t_now); print_sched_event(tid, msg_buf); @@ -843,7 +853,7 @@ void complete_blocked_syscalls ( void ) /* Mark slot as no longer in use. */ vg_waiting_fds[i].fd = -1; /* pp_sched_status(); */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf,"resume due to I/O completion on fd %d", fd); print_sched_event(tid, msg_buf); } @@ -1205,7 +1215,7 @@ void do_pthread_cancel ( ThreadId tid_canceller, do_pthread_create_bogusRA with PTHREAD_CANCELED as the return value. So: simple: put PTHREAD_CANCELED into %EAX and &do_pthread_create_bogusRA into %EIP and keep going! */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "cancelled by %d", tid_canceller); print_sched_event(tid_cancellee, msg_buf); } @@ -1237,7 +1247,7 @@ void do_pthread_create_exit_by_returning ( ThreadId tid ) if (vg_threads[tid].joiner == VG_INVALID_THREADID) { /* No one has yet done a join on me */ vg_threads[tid].status = VgTs_WaitJoiner; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "root fn returns, waiting for a call pthread_join(%d)", tid); @@ -1261,7 +1271,7 @@ void do_pthread_create_exit_by_returning ( ThreadId tid ) vg_threads[jnr].m_edx = 0; /* success */ vg_threads[jnr].status = VgTs_Runnable; vg_threads[tid].status = VgTs_Empty; /* bye! */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "root fn returns, to find a waiting pthread_join(%d)", tid); print_sched_event(tid, msg_buf); @@ -1320,7 +1330,7 @@ void do_pthread_join ( ThreadId tid, ThreadId jee, void** thread_return ) *thread_return = vg_threads[jee].retval; vg_threads[tid].status = VgTs_Runnable; vg_threads[jee].status = VgTs_Empty; /* bye! */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "someone called pthread_join() on me; bye!"); print_sched_event(jee, msg_buf); @@ -1335,7 +1345,7 @@ void do_pthread_join ( ThreadId tid, ThreadId jee, void** thread_return ) /* Ok, so we'll have to wait on jee. */ vg_threads[jee].joiner = tid; vg_threads[tid].status = VgTs_WaitJoinee; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "blocking on call of pthread_join(%d)", jee ); print_sched_event(tid, msg_buf); @@ -1408,7 +1418,7 @@ void do_pthread_create ( ThreadId parent_tid, /* this is where we start */ vg_threads[tid].m_eip = (UInt)start_routine; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "new thread, created by %d", parent_tid ); print_sched_event(tid, msg_buf); @@ -1447,18 +1457,23 @@ void do_pthread_create ( ThreadId parent_tid, */ static -void initialise_mutex ( pthread_mutex_t *mutex ) +void initialise_mutex ( ThreadId tid, pthread_mutex_t *mutex ) { - MutexId mid; + MutexId mid; + Char msg_buf[100]; /* vg_alloc_MutexId aborts if we can't allocate a mutex, for whatever reason. */ -VG_(printf)("initialise_mutex %p\n", mutex); mid = vg_alloc_VgMutex(); vg_mutexes[mid].in_use = True; vg_mutexes[mid].held = False; vg_mutexes[mid].owner = VG_INVALID_THREADID; /* irrelevant */ mutex->__m_reserved = mid; mutex->__m_count = 1; /* initialised */ + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "(initialise mutex) (%p) -> %d", + mutex, mid ); + print_pthread_event(tid, msg_buf); + } } /* Allocate a new MutexId and write it into *mutex. Ideally take @@ -1468,12 +1483,18 @@ void do_pthread_mutex_init ( ThreadId tid, pthread_mutex_t *mutex, const pthread_mutexattr_t *mutexattr) { + Char msg_buf[100]; /* Paranoia ... */ -VG_(printf)("mutex_init %d %p %p\n", tid, mutex, mutexattr); - vg_assert(sizeof(pthread_mutex_t) >= sizeof(UInt)); - initialise_mutex(mutex); + initialise_mutex(tid, mutex); + + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_init (%p) -> %d", + mutex, mutex->__m_reserved ); + print_pthread_event(tid, msg_buf); + } + /* RETURN VALUE pthread_mutex_init always returns 0. The other mutex functions @@ -1490,8 +1511,6 @@ void do_pthread_mutex_lock( ThreadId tid, pthread_mutex_t *mutex ) MutexId mid; Char msg_buf[100]; -VG_(printf)("mutex_lock %d %p\n", tid, mutex); - /* *mutex contains the MutexId, or one of the magic values PTHREAD_*MUTEX_INITIALIZER*, indicating we need to initialise it now. See comment(s) above re use of __m_count to indicated @@ -1505,7 +1524,7 @@ VG_(printf)("mutex_lock %d %p\n", tid, mutex); } if (mutex->__m_count == 0) { - initialise_mutex(mutex); + initialise_mutex(tid, mutex); } mid = mutex->__m_reserved; @@ -1514,6 +1533,12 @@ VG_(printf)("mutex_lock %d %p\n", tid, mutex); return; } + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_lock %d (%p)", + mid, mutex ); + print_pthread_event(tid, msg_buf); + } + /* Assert initialised. */ vg_assert(mutex->__m_count == 1); @@ -1529,9 +1554,10 @@ VG_(printf)("mutex_lock %d %p\n", tid, mutex); vg_threads[tid].status = VgTs_WaitMX; vg_threads[tid].waited_on_mid = mid; /* No assignment to %EDX, since we're blocking. */ - if (1) { - VG_(sprintf)(msg_buf, "wait for mutex %d", mid ); - print_sched_event(tid, msg_buf); + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_lock %d (%p): BLOCK", + mid, mutex ); + print_pthread_event(tid, msg_buf); } } else { /* We get it! */ @@ -1551,8 +1577,6 @@ void do_pthread_mutex_unlock ( ThreadId tid, Int i; Char msg_buf[100]; -VG_(printf)("mutex_unlock %d %p\n", tid, mutex); - if (mutex == NULL || mutex->__m_count != 1) { vg_threads[tid].m_edx = EINVAL; @@ -1565,6 +1589,12 @@ VG_(printf)("mutex_unlock %d %p\n", tid, mutex); return; } + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_unlock %d (%p)", + mid, mutex ); + print_pthread_event(tid, msg_buf); + } + /* Assume tid valid */ vg_assert(vg_threads[tid].status == VgTs_Runnable); @@ -1594,9 +1624,11 @@ VG_(printf)("mutex_unlock %d %p\n", tid, mutex); vg_mutexes[mid].owner = i; vg_threads[i].status = VgTs_Runnable; vg_threads[i].m_edx = 0; /* pth_lock() success */ - if (1) { - VG_(sprintf)(msg_buf, "acquire mutex %d, resume", mid ); - print_sched_event(tid, msg_buf); + + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_lock %d: RESUME", + mid ); + print_pthread_event(tid, msg_buf); } } @@ -1609,9 +1641,8 @@ VG_(printf)("mutex_unlock %d %p\n", tid, mutex); static void do_pthread_mutex_destroy ( ThreadId tid, pthread_mutex_t *mutex ) { - MutexId mid; - -VG_(printf)("mutex_destroy %d %p\n", tid, mutex); + MutexId mid; + Char msg_buf[100]; if (mutex == NULL || mutex->__m_count != 1) { @@ -1625,6 +1656,12 @@ VG_(printf)("mutex_destroy %d %p\n", tid, mutex); return; } + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_destroy %d (%p)", + mid, mutex ); + print_pthread_event(tid, msg_buf); + } + /* Assume tid valid */ vg_assert(vg_threads[tid].status == VgTs_Runnable); diff --git a/valgrind.in b/valgrind.in index bc4594004c..35249d9a9e 100755 --- a/valgrind.in +++ b/valgrind.in @@ -87,6 +87,10 @@ do --trace-symtab=no) vgopts="$vgopts $arg"; shift;; --trace-malloc=yes) vgopts="$vgopts $arg"; shift;; --trace-malloc=no) vgopts="$vgopts $arg"; shift;; + --trace-sched=yes) vgopts="$vgopts $arg"; shift;; + --trace-sched=no) vgopts="$vgopts $arg"; shift;; + --trace-pthread=yes) vgopts="$vgopts $arg"; shift;; + --trace-pthread=no) vgopts="$vgopts $arg"; shift;; --stop-after=*) vgopts="$vgopts $arg"; shift;; --dump-error=*) vgopts="$vgopts $arg"; shift;; -*) dousage=1; break;; @@ -146,6 +150,8 @@ if [ z"$argopts" = z -o z"$dousage" = z1 ]; then echo " --trace-signals=no|yes show signal handling details? [no]" echo " --trace-symtab=no|yes show symbol table details? [no]" echo " --trace-malloc=no|yes show client malloc details? [no]" + echo " --trace-sched=no|yes show thread scheduler details? [no]" + echo " --trace-pthread=no|yes show pthread event details? [no]" echo " --stop-after= switch to real CPU after executing" echo " basic blocks [infinity]" echo " --dump-error= show translation for basic block" diff --git a/vg_include.h b/vg_include.h index 5d9825f12d..56ee85d13e 100644 --- a/vg_include.h +++ b/vg_include.h @@ -242,6 +242,10 @@ extern Bool VG_(clo_trace_signals); extern Bool VG_(clo_trace_symtab); /* DEBUG: print malloc details? default: NO */ extern Bool VG_(clo_trace_malloc); +/* DEBUG: print thread scheduling events? default: NO */ +extern Bool VG_(clo_trace_sched); +/* DEBUG: print pthread (mutex etc) events? default: NO */ +extern Bool VG_(clo_trace_pthread); /* Stop after this many basic blocks. default: Infinity. */ extern ULong VG_(clo_stop_after); /* Display gory details for the k'th most popular error. default: diff --git a/vg_libpthread.c b/vg_libpthread.c index e8d60430be..ca2057a2db 100644 --- a/vg_libpthread.c +++ b/vg_libpthread.c @@ -152,17 +152,17 @@ int* __errno_location ( void ) int pthread_mutexattr_init(pthread_mutexattr_t *attr) { - char* str = "pthread_mutexattr_init\n"; - write(2, str, strlen(str)); - return 0; + char* str = "IGNORED pthread_mutexattr_init\n"; + write(2, str, strlen(str)); + return 0; } int pthread_mutex_init(pthread_mutex_t *mutex, const pthread_mutexattr_t *mutexattr) { int res; - char* str = "pthread_mutex_init\n"; - write(2, str, strlen(str)); + // char* str = "pthread_mutex_init\n"; + // write(2, str, strlen(str)); ensure_valgrind("pthread_mutex_init"); VALGRIND_MAGIC_SEQUENCE(res, 0 /* default */, VG_USERREQ__PTHREAD_MUTEX_INIT, @@ -172,7 +172,7 @@ int pthread_mutex_init(pthread_mutex_t *mutex, int pthread_mutexattr_destroy(pthread_mutexattr_t *attr) { - char* str = "pthread_mutexattr_destroy\n"; + char* str = "IGNORED pthread_mutexattr_destroy\n"; write(2, str, strlen(str)); return 0; } @@ -237,7 +237,7 @@ int pthread_mutex_destroy(pthread_mutex_t *mutex) int pthread_setcanceltype(int type, int *oldtype) { - char* str = "pthread_setcanceltype\n"; + char* str = "IGNORED pthread_setcanceltype\n"; write(2, str, strlen(str)); return 0; } diff --git a/vg_main.c b/vg_main.c index 6e5c01ab03..128bfddff3 100644 --- a/vg_main.c +++ b/vg_main.c @@ -439,6 +439,8 @@ Bool VG_(clo_trace_syscalls); Bool VG_(clo_trace_signals); Bool VG_(clo_trace_symtab); Bool VG_(clo_trace_malloc); +Bool VG_(clo_trace_sched); +Bool VG_(clo_trace_pthread); ULong VG_(clo_stop_after); Int VG_(clo_dump_error); Int VG_(clo_backtrace_size); @@ -521,6 +523,8 @@ static void process_cmd_line_options ( void ) VG_(clo_trace_signals) = False; VG_(clo_trace_symtab) = False; VG_(clo_trace_malloc) = False; + VG_(clo_trace_sched) = False; + VG_(clo_trace_pthread) = False; VG_(clo_stop_after) = 1000000000000LL; VG_(clo_dump_error) = 0; VG_(clo_backtrace_size) = 4; @@ -789,6 +793,16 @@ static void process_cmd_line_options ( void ) else if (STREQ(argv[i], "--trace-malloc=no")) VG_(clo_trace_malloc) = False; + else if (STREQ(argv[i], "--trace-sched=yes")) + VG_(clo_trace_sched) = True; + else if (STREQ(argv[i], "--trace-sched=no")) + VG_(clo_trace_sched) = False; + + else if (STREQ(argv[i], "--trace-pthread=yes")) + VG_(clo_trace_pthread) = True; + else if (STREQ(argv[i], "--trace-pthread=no")) + VG_(clo_trace_pthread) = False; + else if (STREQN(13, argv[i], "--stop-after=")) VG_(clo_stop_after) = VG_(atoll)(&argv[i][13]); diff --git a/vg_scheduler.c b/vg_scheduler.c index c1a26ad2c9..f75fcce8a6 100644 --- a/vg_scheduler.c +++ b/vg_scheduler.c @@ -50,7 +50,11 @@ anyone at all! - return bogus RA: %EAX trashed, so pthread_joiner gets nonsense exit codes -- when a thread is done mark its stack as noaccess */ +- when a thread is done mark its stack as noaccess + +- make signal return and .fini call be detected via request mechanism + + */ /* --------------------------------------------------------------------- @@ -166,8 +170,14 @@ void add_waiting_fd ( ThreadId tid, Int fd, Int syscall_no ) static void print_sched_event ( ThreadId tid, Char* what ) { - if (1) - VG_(message)(Vg_DebugMsg, "SCHED[%d]: %s", tid, what ); + VG_(message)(Vg_DebugMsg, "SCHED[%d]: %s", tid, what ); +} + + +static +void print_pthread_event ( ThreadId tid, Char* what ) +{ + VG_(message)(Vg_DebugMsg, "PTHREAD[%d]: %s", tid, what ); } @@ -566,7 +576,7 @@ void sched_do_syscall ( ThreadId tid ) + (ULong)( (UInt)(req->tv_nsec) / 1000 ); vg_threads[tid].status = VgTs_Sleeping; vg_threads[tid].awaken_at = t_awaken; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "at %lu: nanosleep for %lu", t_now, t_awaken-t_now); print_sched_event(tid, msg_buf); @@ -642,7 +652,7 @@ void sched_do_syscall ( ThreadId tid ) add_waiting_fd(tid, fd, saved_eax /* which holds the syscall # */); /* Deschedule thread until an I/O completion happens. */ vg_threads[tid].status = VgTs_WaitFD; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf,"block until I/O ready on fd %d", fd); print_sched_event(tid, msg_buf); } @@ -702,7 +712,7 @@ void poll_for_ready_fds ( void ) vg_threads[tid].m_eax = 0; /* Reschedule this thread. */ vg_threads[tid].status = VgTs_Runnable; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "at %lu: nanosleep done", t_now); print_sched_event(tid, msg_buf); @@ -843,7 +853,7 @@ void complete_blocked_syscalls ( void ) /* Mark slot as no longer in use. */ vg_waiting_fds[i].fd = -1; /* pp_sched_status(); */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf,"resume due to I/O completion on fd %d", fd); print_sched_event(tid, msg_buf); } @@ -1205,7 +1215,7 @@ void do_pthread_cancel ( ThreadId tid_canceller, do_pthread_create_bogusRA with PTHREAD_CANCELED as the return value. So: simple: put PTHREAD_CANCELED into %EAX and &do_pthread_create_bogusRA into %EIP and keep going! */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "cancelled by %d", tid_canceller); print_sched_event(tid_cancellee, msg_buf); } @@ -1237,7 +1247,7 @@ void do_pthread_create_exit_by_returning ( ThreadId tid ) if (vg_threads[tid].joiner == VG_INVALID_THREADID) { /* No one has yet done a join on me */ vg_threads[tid].status = VgTs_WaitJoiner; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "root fn returns, waiting for a call pthread_join(%d)", tid); @@ -1261,7 +1271,7 @@ void do_pthread_create_exit_by_returning ( ThreadId tid ) vg_threads[jnr].m_edx = 0; /* success */ vg_threads[jnr].status = VgTs_Runnable; vg_threads[tid].status = VgTs_Empty; /* bye! */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "root fn returns, to find a waiting pthread_join(%d)", tid); print_sched_event(tid, msg_buf); @@ -1320,7 +1330,7 @@ void do_pthread_join ( ThreadId tid, ThreadId jee, void** thread_return ) *thread_return = vg_threads[jee].retval; vg_threads[tid].status = VgTs_Runnable; vg_threads[jee].status = VgTs_Empty; /* bye! */ - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "someone called pthread_join() on me; bye!"); print_sched_event(jee, msg_buf); @@ -1335,7 +1345,7 @@ void do_pthread_join ( ThreadId tid, ThreadId jee, void** thread_return ) /* Ok, so we'll have to wait on jee. */ vg_threads[jee].joiner = tid; vg_threads[tid].status = VgTs_WaitJoinee; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "blocking on call of pthread_join(%d)", jee ); print_sched_event(tid, msg_buf); @@ -1408,7 +1418,7 @@ void do_pthread_create ( ThreadId parent_tid, /* this is where we start */ vg_threads[tid].m_eip = (UInt)start_routine; - if (1) { + if (VG_(clo_trace_sched)) { VG_(sprintf)(msg_buf, "new thread, created by %d", parent_tid ); print_sched_event(tid, msg_buf); @@ -1447,18 +1457,23 @@ void do_pthread_create ( ThreadId parent_tid, */ static -void initialise_mutex ( pthread_mutex_t *mutex ) +void initialise_mutex ( ThreadId tid, pthread_mutex_t *mutex ) { - MutexId mid; + MutexId mid; + Char msg_buf[100]; /* vg_alloc_MutexId aborts if we can't allocate a mutex, for whatever reason. */ -VG_(printf)("initialise_mutex %p\n", mutex); mid = vg_alloc_VgMutex(); vg_mutexes[mid].in_use = True; vg_mutexes[mid].held = False; vg_mutexes[mid].owner = VG_INVALID_THREADID; /* irrelevant */ mutex->__m_reserved = mid; mutex->__m_count = 1; /* initialised */ + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "(initialise mutex) (%p) -> %d", + mutex, mid ); + print_pthread_event(tid, msg_buf); + } } /* Allocate a new MutexId and write it into *mutex. Ideally take @@ -1468,12 +1483,18 @@ void do_pthread_mutex_init ( ThreadId tid, pthread_mutex_t *mutex, const pthread_mutexattr_t *mutexattr) { + Char msg_buf[100]; /* Paranoia ... */ -VG_(printf)("mutex_init %d %p %p\n", tid, mutex, mutexattr); - vg_assert(sizeof(pthread_mutex_t) >= sizeof(UInt)); - initialise_mutex(mutex); + initialise_mutex(tid, mutex); + + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_init (%p) -> %d", + mutex, mutex->__m_reserved ); + print_pthread_event(tid, msg_buf); + } + /* RETURN VALUE pthread_mutex_init always returns 0. The other mutex functions @@ -1490,8 +1511,6 @@ void do_pthread_mutex_lock( ThreadId tid, pthread_mutex_t *mutex ) MutexId mid; Char msg_buf[100]; -VG_(printf)("mutex_lock %d %p\n", tid, mutex); - /* *mutex contains the MutexId, or one of the magic values PTHREAD_*MUTEX_INITIALIZER*, indicating we need to initialise it now. See comment(s) above re use of __m_count to indicated @@ -1505,7 +1524,7 @@ VG_(printf)("mutex_lock %d %p\n", tid, mutex); } if (mutex->__m_count == 0) { - initialise_mutex(mutex); + initialise_mutex(tid, mutex); } mid = mutex->__m_reserved; @@ -1514,6 +1533,12 @@ VG_(printf)("mutex_lock %d %p\n", tid, mutex); return; } + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_lock %d (%p)", + mid, mutex ); + print_pthread_event(tid, msg_buf); + } + /* Assert initialised. */ vg_assert(mutex->__m_count == 1); @@ -1529,9 +1554,10 @@ VG_(printf)("mutex_lock %d %p\n", tid, mutex); vg_threads[tid].status = VgTs_WaitMX; vg_threads[tid].waited_on_mid = mid; /* No assignment to %EDX, since we're blocking. */ - if (1) { - VG_(sprintf)(msg_buf, "wait for mutex %d", mid ); - print_sched_event(tid, msg_buf); + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_lock %d (%p): BLOCK", + mid, mutex ); + print_pthread_event(tid, msg_buf); } } else { /* We get it! */ @@ -1551,8 +1577,6 @@ void do_pthread_mutex_unlock ( ThreadId tid, Int i; Char msg_buf[100]; -VG_(printf)("mutex_unlock %d %p\n", tid, mutex); - if (mutex == NULL || mutex->__m_count != 1) { vg_threads[tid].m_edx = EINVAL; @@ -1565,6 +1589,12 @@ VG_(printf)("mutex_unlock %d %p\n", tid, mutex); return; } + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_unlock %d (%p)", + mid, mutex ); + print_pthread_event(tid, msg_buf); + } + /* Assume tid valid */ vg_assert(vg_threads[tid].status == VgTs_Runnable); @@ -1594,9 +1624,11 @@ VG_(printf)("mutex_unlock %d %p\n", tid, mutex); vg_mutexes[mid].owner = i; vg_threads[i].status = VgTs_Runnable; vg_threads[i].m_edx = 0; /* pth_lock() success */ - if (1) { - VG_(sprintf)(msg_buf, "acquire mutex %d, resume", mid ); - print_sched_event(tid, msg_buf); + + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_lock %d: RESUME", + mid ); + print_pthread_event(tid, msg_buf); } } @@ -1609,9 +1641,8 @@ VG_(printf)("mutex_unlock %d %p\n", tid, mutex); static void do_pthread_mutex_destroy ( ThreadId tid, pthread_mutex_t *mutex ) { - MutexId mid; - -VG_(printf)("mutex_destroy %d %p\n", tid, mutex); + MutexId mid; + Char msg_buf[100]; if (mutex == NULL || mutex->__m_count != 1) { @@ -1625,6 +1656,12 @@ VG_(printf)("mutex_destroy %d %p\n", tid, mutex); return; } + if (VG_(clo_trace_pthread)) { + VG_(sprintf)(msg_buf, "pthread_mutex_destroy %d (%p)", + mid, mutex ); + print_pthread_event(tid, msg_buf); + } + /* Assume tid valid */ vg_assert(vg_threads[tid].status == VgTs_Runnable);