Remove sys/user time in -ftime-report

Retrieving sys/user time in timevars is quite expensive because it
always needs a system call. Only getting the wall time is much
cheaper because operating systems have optimized paths for this.

The sys time isn't that interesting for a compiler and wall time
is usually close to user time except when the system is overloaded.
On the other hand when it is not wall time is more accurate because
it has less overhead.

For building tramp3d with -O0 the -ftime-report overhead drops from
18% to 3%. For -O2 it drops from 8% to not measurable.

I changed the code to use gettimeofday as a fallback for clock_gettime
CLOCK_MONOTONIC.  If a host has neither of those the time will not
be measured. Previously clock was the fallback.

This removes a lot of code in timevar.cc:

 gcc/timevar.cc | 167 ++++++---------------------------------------------------
 gcc/timevar.h  |  10 +---

 2 files changed, 17 insertions(+), 160 deletions(-)

gcc/ChangeLog:

	* timevar.cc (struct tms): Remove.
	(RUSAGE_SELF): Remove.
	(TICKS_PER_SECOND): Remove.
	(USE_TIMES): Remove.
	(HAVE_USER_TIME): Remove.
	(HAVE_SYS_TIME): Remove.
	(HAVE_WALL_TIME): Remove.
	(USE_GETRUSAGE): Remove.
	(USE_CLOCK): Remove.
	(NANOSEC_PER_SEC): Remove.
	(TICKS_TO_NANOSEC): Remove.
	(CLOCKS_TO_NANOSEC): Remove.
	(timer::named_items::push): Remove sys/user.
	(get_time): Remove clock and times and getruage code.
	(timevar_accumulate): Remove sys/user.
	(timevar_diff): Dito.
	(timer::validate_phases): Dito.
	(timer::print_row): Dito.
	(timer::all_zero): Dito.
	(timer::print): Dito.
	(make_json_for_timevar_time_def): Dito.
	* timevar.h (struct timevar_time_def): Dito.
This commit is contained in:
Andi Kleen 2024-10-02 13:13:21 -07:00
parent 8f9348361c
commit a2cd5d1f10
2 changed files with 22 additions and 177 deletions

View File

@ -26,84 +26,6 @@ along with GCC; see the file COPYING3. If not see
#include "options.h"
#include "json.h"
#ifndef HAVE_CLOCK_T
typedef int clock_t;
#endif
#ifndef HAVE_STRUCT_TMS
struct tms
{
clock_t tms_utime;
clock_t tms_stime;
clock_t tms_cutime;
clock_t tms_cstime;
};
#endif
#ifndef RUSAGE_SELF
# define RUSAGE_SELF 0
#endif
/* Calculation of scale factor to convert ticks to seconds.
We mustn't use CLOCKS_PER_SEC except with clock(). */
#if HAVE_SYSCONF && defined _SC_CLK_TCK
# define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
#else
# ifdef CLK_TCK
# define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
# else
# ifdef HZ
# define TICKS_PER_SECOND HZ /* traditional UNIX */
# else
# define TICKS_PER_SECOND 100 /* often the correct value */
# endif
# endif
#endif
/* Prefer times to getrusage to clock (each gives successively less
information). */
#ifdef HAVE_TIMES
# if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
extern clock_t times (struct tms *);
# endif
# define USE_TIMES
# define HAVE_USER_TIME
# define HAVE_SYS_TIME
# define HAVE_WALL_TIME
#else
#ifdef HAVE_GETRUSAGE
# if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
extern int getrusage (int, struct rusage *);
# endif
# define USE_GETRUSAGE
# define HAVE_USER_TIME
# define HAVE_SYS_TIME
#else
#ifdef HAVE_CLOCK
# if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
extern clock_t clock (void);
# endif
# define USE_CLOCK
# define HAVE_USER_TIME
#endif
#endif
#endif
/* libc is very likely to have snuck a call to sysconf() into one of
the underlying constants, and that can be very slow, so we have to
precompute them. Whose wonderful idea was it to make all those
_constants_ variable at run time, anyway? */
#define NANOSEC_PER_SEC 1000000000
#ifdef USE_TIMES
static uint64_t ticks_to_nanosec;
#define TICKS_TO_NANOSEC (NANOSEC_PER_SEC / TICKS_PER_SECOND)
#endif
#ifdef USE_CLOCK
static uint64_t clocks_to_nanosec;
#define CLOCKS_TO_NANOSEC (NANOSEC_PER_SEC / CLOCKS_PER_SEC)
#endif
/* Non-NULL if timevars should be used. In GCC, this happens with
the -ftime-report flag. */
@ -181,8 +103,6 @@ timer::named_items::push (const char *item_name)
timer::timevar_def *def = &m_hash_map.get_or_insert (item_name, &existed);
if (!existed)
{
def->elapsed.user = 0;
def->elapsed.sys = 0;
def->elapsed.wall = 0;
def->name = item_name;
def->standalone = 0;
@ -230,37 +150,27 @@ timer::named_items::make_json () const
return arr;
}
/* Fill the current times into TIME. The definition of this function
also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
HAVE_WALL_TIME macros. */
/* Fill the current times into TIME, and define HAVE_WALL_TIME if there. */
static void
get_time (struct timevar_time_def *now)
{
now->user = 0;
now->sys = 0;
now->wall = 0;
now->ggc_mem = timevar_ggc_mem_total;
{
#ifdef USE_TIMES
struct tms tms;
now->wall = times (&tms) * ticks_to_nanosec;
now->user = tms.tms_utime * ticks_to_nanosec;
now->sys = tms.tms_stime * ticks_to_nanosec;
#if _POSIX_C_SOURCE >= 199309L
struct timespec ts;
clock_gettime (CLOCK_MONOTONIC, &ts);
now->wall = ts.tv_sec * 1000000000 + ts.tv_nsec;
return;
#define HAVE_WALL_TIME 1
#endif
#ifdef USE_GETRUSAGE
struct rusage rusage;
getrusage (RUSAGE_SELF, &rusage);
now->user = rusage.ru_utime.tv_sec * NANOSEC_PER_SEC
+ rusage.ru_utime.tv_usec * 1000;
now->sys = rusage.ru_stime.tv_sec * NANOSEC_PER_SEC
+ rusage.ru_stime.tv_usec * 1000;
#ifdef HAVE_GETTIMEOFDAY
struct timeval tv;
gettimeofday (&tv, NULL);
now->wall = tv.tv_sec * 1000000000 + tv.tv_usec * 1000;
#define HAVE_WALL_TIME 1
#endif
#ifdef USE_CLOCK
now->user = clock () * clocks_to_nanosec;
#endif
}
}
/* Add the difference between STOP_TIME and START_TIME to TIMER. */
@ -270,8 +180,6 @@ timevar_accumulate (struct timevar_time_def *timer,
struct timevar_time_def *start_time,
struct timevar_time_def *stop_time)
{
timer->user += stop_time->user - start_time->user;
timer->sys += stop_time->sys - start_time->sys;
timer->wall += stop_time->wall - start_time->wall;
timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
}
@ -283,8 +191,6 @@ timevar_diff (struct timevar_time_def *out,
const timevar_time_def &start_time,
const timevar_time_def &stop_time)
{
out->user = stop_time.user - start_time.user;
out->sys = stop_time.sys - start_time.sys;
out->wall = stop_time.wall - start_time.wall;
out->ggc_mem = stop_time.ggc_mem - start_time.ggc_mem;
}
@ -305,15 +211,6 @@ timer::timer () :
m_timevars[identifier__].name = name__;
#include "timevar.def"
#undef DEFTIMEVAR
/* Initialize configuration-specific state.
Ideally this would be one-time initialization. */
#ifdef USE_TIMES
ticks_to_nanosec = TICKS_TO_NANOSEC;
#endif
#ifdef USE_CLOCK
clocks_to_nanosec = CLOCKS_TO_NANOSEC;
#endif
}
/* Class timer's destructor. */
@ -621,8 +518,6 @@ timer::validate_phases (FILE *fp) const
{
unsigned int /* timevar_id_t */ id;
const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
uint64_t phase_user = 0;
uint64_t phase_sys = 0;
uint64_t phase_wall = 0;
size_t phase_ggc_mem = 0;
static char phase_prefix[] = "phase ";
@ -637,26 +532,15 @@ timer::validate_phases (FILE *fp) const
if (startswith (tv->name, phase_prefix))
{
phase_user += tv->elapsed.user;
phase_sys += tv->elapsed.sys;
phase_wall += tv->elapsed.wall;
phase_ggc_mem += tv->elapsed.ggc_mem;
}
}
if (phase_user > total->user
|| phase_sys > total->sys
|| phase_wall > total->wall
|| phase_ggc_mem > total->ggc_mem)
if (phase_wall > total->wall || phase_ggc_mem > total->ggc_mem)
{
fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
if (phase_user > total->user)
fprintf (fp, "user %13" PRIu64 " > %13" PRIu64 "\n",
phase_user, total->user);
if (phase_sys > total->sys)
fprintf (fp, "sys %13" PRIu64 " > %13" PRIu64 "\n",
phase_sys, total->sys);
if (phase_wall > total->wall)
fprintf (fp, "wall %13" PRIu64 " > %13" PRIu64 "\n",
phase_wall, total->wall);
@ -680,20 +564,6 @@ timer::print_row (FILE *fp,
/* The timing variable name. */
fprintf (fp, " %-35s:", name);
#ifdef HAVE_USER_TIME
/* Print user-mode time for this process. */
fprintf (fp, "%7.2f (%3.0f%%)",
nanosec_to_floating_sec (elapsed.user),
percent_of (total->user, elapsed.user));
#endif /* HAVE_USER_TIME */
#ifdef HAVE_SYS_TIME
/* Print system-mode time for this process. */
fprintf (fp, "%7.2f (%3.0f%%)",
nanosec_to_floating_sec (elapsed.sys),
percent_of (total->sys, elapsed.sys));
#endif /* HAVE_SYS_TIME */
#ifdef HAVE_WALL_TIME
/* Print wall clock time elapsed. */
fprintf (fp, "%7.2f (%3.0f%%)",
@ -718,9 +588,7 @@ timer::all_zero (const timevar_time_def &elapsed)
{
/* 5000000 nanosec == 5e-3 seconds. */
uint64_t tiny = 5000000;
return (elapsed.user < tiny
&& elapsed.sys < tiny
&& elapsed.wall < tiny
return (elapsed.wall < tiny
&& elapsed.ggc_mem < GGC_MEM_BOUND);
}
@ -732,7 +600,7 @@ void
timer::print (FILE *fp)
{
/* Only print stuff if we have some sort of time information. */
#if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
#if defined (HAVE_WALL_TIME)
unsigned int /* timevar_id_t */ id;
const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
struct timevar_time_def now;
@ -754,8 +622,7 @@ timer::print (FILE *fp)
TIMEVAR. */
m_start_time = now;
fprintf (fp, "\n%-35s%16s%14s%14s%14s\n", "Time variable", "usr", "sys",
"wall", "GGC");
fprintf (fp, "\n%-35s%16s%14s\n", "Time variable", "wall", "GGC");
if (m_jit_client_items)
fputs ("GCC items:\n", fp);
for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
@ -809,15 +676,7 @@ timer::print (FILE *fp)
/* Print total time. */
fprintf (fp, " %-35s:", "TOTAL");
#ifdef HAVE_USER_TIME
fprintf (fp, "%7.2f ", nanosec_to_floating_sec (total->user));
#endif
#ifdef HAVE_SYS_TIME
fprintf (fp, "%8.2f ", nanosec_to_floating_sec (total->sys));
#endif
#ifdef HAVE_WALL_TIME
fprintf (fp, "%8.2f ", nanosec_to_floating_sec (total->wall));
#endif
fprintf (fp, "%7.2f ", nanosec_to_floating_sec (total->wall));
fprintf (fp, PRsa (7) "\n", SIZE_AMOUNT (total->ggc_mem));
if (CHECKING_P || flag_checking)
@ -829,8 +688,7 @@ timer::print (FILE *fp)
fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
#endif
#endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
|| defined (HAVE_WALL_TIME) */
#endif /* defined (HAVE_WALL_TIME) */
validate_phases (fp);
}
@ -842,8 +700,6 @@ json::object *
make_json_for_timevar_time_def (const timevar_time_def &ttd)
{
json::object *obj = new json::object ();
obj->set_float ("user", nanosec_to_floating_sec (ttd.user));
obj->set_float ("sys", nanosec_to_floating_sec (ttd.sys));
obj->set_float ("wall", nanosec_to_floating_sec (ttd.wall));
obj->set_integer ("ggc_mem", ttd.ggc_mem);
return obj;
@ -898,8 +754,7 @@ timer::timevar_def::make_json () const
json::value *
timer::make_json () const
{
/* Only generate stuff if we have some sort of time information. */
#if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
#if defined (HAVE_WALL_TIME)
json::object *report_obj = new json::object ();
json::array *json_arr = new json::array ();
report_obj->set ("timevars", json_arr);
@ -958,11 +813,9 @@ timer::make_json () const
return report_obj;
#else /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
|| defined (HAVE_WALL_TIME) */
#else /* defined (HAVE_USER_TIME) */
return NULL;
#endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
|| defined (HAVE_WALL_TIME) */
#endif /* !defined (HAVE_WALL_TIME) */
}
/* Get the name of the topmost item. For use by jit for validating

View File

@ -24,9 +24,7 @@
namespace json { class value; }
/* Timing variables are used to measure elapsed time in various
portions of the compiler. Each measures elapsed user, system, and
wall-clock time, as appropriate to and supported by the host
system.
portions of the compiler. Each measures wall time.
Timing variables are defined using the DEFTIMEVAR macro in
timevar.def. Each has an enumeral identifier, used when referring
@ -53,12 +51,6 @@ namespace json { class value; }
struct timevar_time_def
{
/* User time in this process. */
uint64_t user;
/* System time (if applicable for this host platform) in this process. */
uint64_t sys;
/* Wall clock time. */
uint64_t wall;