Revision: 23589 http://trac.macosforge.org/projects/launchd/changeset/23589 Author: zarzycki@apple.com Date: 2008-04-02 13:57:44 -0700 (Wed, 02 Apr 2008) Log Message: ----------- <rdar://problem/5834789> Observably inaccurate logging during shutdown (exit duration) Modified Paths: -------------- trunk/launchd/src/launchd_core_logic.c trunk/launchd/src/launchd_runtime.c trunk/launchd/src/launchd_runtime.h Modified: trunk/launchd/src/launchd_core_logic.c =================================================================== --- trunk/launchd/src/launchd_core_logic.c 2008-04-02 20:26:26 UTC (rev 23588) +++ trunk/launchd/src/launchd_core_logic.c 2008-04-02 20:57:44 UTC (rev 23589) @@ -2326,13 +2326,12 @@ } if (j->sent_sigterm_time) { - uint64_t td_sec, td_usec, td = runtime_opaque_time_to_nano(runtime_get_opaque_time() - j->sent_sigterm_time); + uint64_t td_sec, td_usec, td = runtime_get_nanoseconds_since(j->sent_sigterm_time); td_sec = td / NSEC_PER_SEC; td_usec = (td % NSEC_PER_SEC) / NSEC_PER_USEC; - job_log(j, LOG_INFO, "Exited %lld.%06lld seconds after %s was sent", - td_sec, td_usec, signal_to_C_name(j->sent_sigkill ? SIGKILL : SIGTERM)); + job_log(j, LOG_INFO, "Exited %lld.%06lld seconds after %s was sent", td_sec, td_usec, signal_to_C_name(SIGTERM)); } #if DO_RUSAGE_SUMMATION @@ -2620,7 +2619,7 @@ job_dispatch(j, false); } else if (&j->exit_timeout == ident) { if (j->sent_sigkill) { - uint64_t td = runtime_opaque_time_to_nano(runtime_get_opaque_time() - j->sent_sigterm_time); + uint64_t td = runtime_get_nanoseconds_since(j->sent_sigterm_time); td /= NSEC_PER_SEC; td -= j->exit_timeout; @@ -2752,7 +2751,7 @@ void job_start(job_t j) { - uint64_t td, tnow = runtime_get_opaque_time(); + uint64_t td; int spair[2]; int execspair[2]; int oepair[2]; @@ -2770,14 +2769,12 @@ return; } - job_assumes(j, tnow > j->start_time); - /* * Some users adjust the wall-clock and then expect software to not notice. * Therefore, launchd must use an absolute clock instead of the wall clock * wherever possible. */ - td = runtime_opaque_time_to_nano(tnow - j->start_time); + td = runtime_get_nanoseconds_since(j->start_time); td /= NSEC_PER_SEC; if (j->start_time && (td < j->min_run_time) && !j->legacy_mach_job && !j->inetcompat) { @@ -2814,8 +2811,6 @@ job_assumes(j, kevent_mod(j->log_redirect_fd, EVFILT_READ, EV_ADD, 0, 0, j) != -1); } - j->start_time = tnow; - switch (c = runtime_fork(j->weird_bootstrap ? j->j_port : j->mgr->jm_port)) { case -1: job_log_error(j, LOG_ERR, "fork() failed, will try again in one second"); @@ -2852,6 +2847,8 @@ job_start_child(j); break; default: + j->start_time = runtime_get_opaque_time(); + job_log(j, LOG_DEBUG, "Started as PID: %u", c); j->start_pending = false; Modified: trunk/launchd/src/launchd_runtime.c =================================================================== --- trunk/launchd/src/launchd_runtime.c 2008-04-02 20:26:26 UTC (rev 23588) +++ trunk/launchd/src/launchd_runtime.c 2008-04-02 20:57:44 UTC (rev 23589) @@ -117,6 +117,7 @@ static void do_file_init(void) __attribute__((constructor)); static mach_timebase_info_data_t tbi; static uint64_t tbi_safe_math_max; +static uint64_t time_of_mach_msg_return; static double tbi_float_val; static const int sigigns[] = { SIGHUP, SIGINT, SIGPIPE, SIGALRM, SIGTERM, @@ -1025,6 +1026,8 @@ mr = mach_msg(&bufReply->Head, tmp_options, bufReply->Head.msgh_size, msg_size, ipc_port_set, to, MACH_PORT_NULL); + time_of_mach_msg_return = runtime_get_opaque_time(); + tmp_options = options; /* It looks like the compiler doesn't optimize switch(unlikely(...)) */ @@ -1639,11 +1642,23 @@ } INTERNAL_ABI uint64_t +runtime_get_opaque_time_of_event(void) +{ + return time_of_mach_msg_return; +} + +INTERNAL_ABI uint64_t +runtime_get_nanoseconds_since(uint64_t o) +{ + return runtime_opaque_time_to_nano(runtime_get_opaque_time_of_event() - o); +} + +INTERNAL_ABI uint64_t runtime_opaque_time_to_nano(uint64_t o) { -#if defined(__i386__) +#if defined(__i386__) || defined(__x86_64__) if (unlikely(tbi.numer != tbi.denom)) { -#elif defined(__ppc__) +#elif defined(__ppc__) || defined(__ppc64__) if (likely(tbi.numer != tbi.denom)) { #else if (tbi.numer != tbi.denom) { Modified: trunk/launchd/src/launchd_runtime.h =================================================================== --- trunk/launchd/src/launchd_runtime.h 2008-04-02 20:26:26 UTC (rev 23588) +++ trunk/launchd/src/launchd_runtime.h 2008-04-02 20:57:44 UTC (rev 23589) @@ -187,9 +187,11 @@ INTERNAL_ABI void runtime_vsyslog(struct runtime_syslog_attr *attr, const char *message, va_list args) __attribute__((format(printf, 2, 0))); INTERNAL_ABI void runtime_log_push(void); -INTERNAL_ABI int64_t runtime_get_wall_time(void); -INTERNAL_ABI uint64_t runtime_get_opaque_time(void); -INTERNAL_ABI uint64_t runtime_opaque_time_to_nano(uint64_t o); +INTERNAL_ABI int64_t runtime_get_wall_time(void) __attribute__((warn_unused_result)); +INTERNAL_ABI uint64_t runtime_get_opaque_time(void) __attribute__((warn_unused_result)); +INTERNAL_ABI uint64_t runtime_get_opaque_time_of_event(void) __attribute__((pure, warn_unused_result)); +INTERNAL_ABI uint64_t runtime_opaque_time_to_nano(uint64_t o) __attribute__((const, warn_unused_result)); +INTERNAL_ABI uint64_t runtime_get_nanoseconds_since(uint64_t o) __attribute__((pure, warn_unused_result)); INTERNAL_ABI kern_return_t launchd_set_bport(mach_port_t name); INTERNAL_ABI kern_return_t launchd_get_bport(mach_port_t *name);