src/common/timers.c

/*****************************************************************************\
 *  timers.c - Timer functions
 *****************************************************************************
 *  Copyright (C) 2002-2006 The Regents of the University of California.
 *  Produced at Lawrence Livermore National Laboratory (cf, DISCLAIMER).
 *  Written by Morris Jette <jette@llnl.gov>
 *  CODE-OCEC-09-009. All rights reserved.
 *
 *  This file is part of Slurm, a resource management program.
 *  For details, see <https://slurm.schedmd.com/>.
 *  Please also read the included file: DISCLAIMER.
 *
 *  Slurm is free software; you can redistribute it and/or modify it under
 *  the terms of the GNU General Public License as published by the Free
 *  Software Foundation; either version 2 of the License, or (at your option)
 *  any later version.
 *
 *  In addition, as a special exception, the copyright holders give permission
 *  to link the code of portions of this program with the OpenSSL library under
 *  certain conditions as described in each individual source file, and
 *  distribute linked combinations including the two. You must obey the GNU
 *  General Public License in all respects for all of the code used other than
 *  OpenSSL. If you modify file(s) with this exception, you may extend this
 *  exception to your version of the file(s), but you are not obligated to do
 *  so. If you do not wish to do so, delete this exception statement from your
 *  version.  If you delete this exception statement from all source files in
 *  the program, then also delete it here.
 *
 *  Slurm is distributed in the hope that it will be useful, but WITHOUT ANY
 *  WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
 *  FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
 *  details.
 *
 *  You should have received a copy of the GNU General Public License along
 *  with Slurm; if not, write to the Free Software Foundation, Inc.,
 *  51 Franklin Street, Fifth Floor, Boston, MA 02110-1301  USA.
\*****************************************************************************/

#include <stdio.h>
#include <sys/time.h>
#include "src/common/log.h"
#include "src/common/slurm_protocol_defs.h"
#include "src/common/slurm_time.h"
#include "src/common/timers.h"
#include "src/common/xassert.h"

/* Return the number of micro-seconds between now and argument "tv",
 * Initialize tv to NOW if zero on entry */
extern int slurm_delta_tv(struct timeval *tv)
{
	struct timeval now = {0, 0};
	int delta_t;

	if (gettimeofday(&now, NULL))
		return 1;		/* Some error */

	if (tv->tv_sec == 0) {
		tv->tv_sec  = now.tv_sec;
		tv->tv_usec = now.tv_usec;
		return 0;
	}

	delta_t  = (now.tv_sec - tv->tv_sec) * 1000000;
	delta_t += (now.tv_usec - tv->tv_usec);

	return delta_t;
}

/*
 * slurm_diff_tv_str - build a string showing the time difference between two
 *		       times
 * IN tv1 - start of event
 * IN tv2 - end of event
 * OUT tv_str - place to put delta time in format "usec=%ld"
 * IN len_tv_str - size of tv_str in bytes
 * IN from - where the function was called form
 */
extern void slurm_diff_tv_str(struct timeval *tv1, struct timeval *tv2,
			      char *tv_str, int len_tv_str, const char *from,
			      long limit, long *delta_t)
{
	char p[64] = "";
	struct tm tm;
	int debug_limit = limit;

	(*delta_t)  = (tv2->tv_sec - tv1->tv_sec) * 1000000;
	(*delta_t) += tv2->tv_usec;
	(*delta_t) -= tv1->tv_usec;
	snprintf(tv_str, len_tv_str, "usec=%ld", *delta_t);
	if (from) {
		if (!limit) {
			/* NOTE: The slurmctld scheduler's default run time
			 * limit is 4 seconds, but that would not typically
			 * be reached. See "max_sched_time=" logic in
			 * src/slurmctld/job_scheduler.c */
			limit = 3000000;
			debug_limit = 1000000;
		}
		if ((*delta_t > debug_limit) || (*delta_t > limit)) {
			if (!localtime_r(&tv1->tv_sec, &tm))
				error("localtime_r(): %m");
			if (strftime(p, sizeof(p), "%T", &tm) == 0)
				error("strftime(): %m");
			if (*delta_t > limit) {
				verbose("Warning: Note very large processing "
					"time from %s: %s began=%s.%3.3d",
					from, tv_str, p,
					(int)(tv1->tv_usec / 1000));
			} else {	/* Log anything over 1 second here */
				debug("Note large processing time from %s: "
				      "%s began=%s.%3.3d",
				      from, tv_str, p,
				      (int)(tv1->tv_usec / 1000));
			}
		}
	}
}

extern void latency_metric_begin(latency_metric_t *metric, timespec_t *start)
{
	xassert(!start->tv_sec);
	*start = timespec_now();
}

extern latency_metric_rc_t latency_metric_end(latency_metric_t *metric,
					      timespec_t *start,
					      const timespec_t interval)
{
	latency_metric_rc_t rc = {0};
	const timespec_t now = timespec_now();

	xassert(start->tv_sec > 0);

	{
		timespec_diff_ns_t diff = timespec_diff_ns(now, *start);
		xassert(diff.after);
		metric->total = timespec_add(metric->total, diff.diff);
		rc.delay = diff.diff;
	}

	*start = (timespec_t) {0};
	metric->count++;

	if (!metric->last_log.tv_sec) {
		/* Set timestamp on full run and skip analysis */
		metric->last_log = now;
		return rc;
	} else {
		timespec_diff_ns_t diff =
			timespec_diff_ns(now, metric->last_log);

		xassert(diff.after);

		if (!timespec_is_after(diff.diff, interval))
			return rc;
	}

	{
		double avg;

		/* Promote all components to double to avoid truncation */
		avg = (double) metric->total.tv_sec;
		avg += ((double) metric->total.tv_sec) / ((double) NSEC_IN_SEC);
		avg /= (double) metric->count;

		rc.avg = avg;
	}

	return rc;
}