Optimization: Use either monotonic or wall-clock to measure command execution time, to regain up to 4% execution time (#10502)

In #7491 (part of redis 6.2), we started using the monotonic timer instead of mstime to measure
command execution time for stats, apparently this meant sampling the clock 3 times per command
rather than two (wince we also need the wall-clock time).
In some cases this causes a significant overhead.

This PR fixes that by avoiding the use of monotonic timer, except for the cases were we know it
should be extremely fast.
This PR also adds a new INFO field called `monotonic_clock` that shows which clock redis is using.

Co-authored-by: Oran Agra <oran@redislabs.com>
This commit is contained in:
filipe oliveira 2022-04-20 12:00:30 +01:00 committed by GitHub
parent ee220599b0
commit 3cd8baf616
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 57 additions and 20 deletions

View File

@ -168,3 +168,13 @@ const char * monotonicInit() {
return monotonic_info_string;
}
const char *monotonicInfoString() {
return monotonic_info_string;
}
monotonic_clock_type monotonicGetType() {
if (getMonotonicUs == getMonotonicUs_posix)
return MONOTONIC_CLOCK_POSIX;
return MONOTONIC_CLOCK_HW;
}

View File

@ -24,13 +24,22 @@ typedef uint64_t monotime;
/* Retrieve counter of micro-seconds relative to an arbitrary point in time. */
extern monotime (*getMonotonicUs)(void);
typedef enum monotonic_clock_type {
MONOTONIC_CLOCK_POSIX,
MONOTONIC_CLOCK_HW,
} monotonic_clock_type;
/* Call once at startup to initialize the monotonic clock. Though this only
* needs to be called once, it may be called additional times without impact.
* Returns a printable string indicating the type of clock initialized.
* (The returned string is static and doesn't need to be freed.) */
const char * monotonicInit();
const char *monotonicInit();
/* Return a string indicating the type of monotonic clock being used. */
const char *monotonicInfoString();
/* Return the type of monotonic clock being used. */
monotonic_clock_type monotonicGetType();
/* Functions to measure elapsed time. Example:
* monotime myTimer;

View File

@ -1015,18 +1015,8 @@ void databasesCron(void) {
}
}
/* We take a cached value of the unix time in the global state because with
* virtual memory and aging there is to store the current time in objects at
* every object access, and accuracy is not needed. To access a global var is
* a lot faster than calling time(NULL).
*
* This function should be fast because it is called at every command execution
* in call(), so it is possible to decide if to update the daylight saving
* info or not using the 'update_daylight_info' argument. Normally we update
* such info only when calling this function from serverCron() but not when
* calling it from call(). */
void updateCachedTime(int update_daylight_info) {
server.ustime = ustime();
static inline void updateCachedTimeWithUs(int update_daylight_info, const long long ustime) {
server.ustime = ustime;
server.mstime = server.ustime / 1000;
time_t unixtime = server.mstime / 1000;
atomicSet(server.unixtime, unixtime);
@ -1044,6 +1034,21 @@ void updateCachedTime(int update_daylight_info) {
}
}
/* We take a cached value of the unix time in the global state because with
* virtual memory and aging there is to store the current time in objects at
* every object access, and accuracy is not needed. To access a global var is
* a lot faster than calling time(NULL).
*
* This function should be fast because it is called at every command execution
* in call(), so it is possible to decide if to update the daylight saving
* info or not using the 'update_daylight_info' argument. Normally we update
* such info only when calling this function from serverCron() but not when
* calling it from call(). */
void updateCachedTime(int update_daylight_info) {
const long long us = ustime();
updateCachedTimeWithUs(update_daylight_info, us);
}
void checkChildrenDone(void) {
int statloc = 0;
pid_t pid;
@ -3208,7 +3213,6 @@ int incrCommandStatsOnError(struct redisCommand *cmd, int flags) {
*/
void call(client *c, int flags) {
long long dirty;
monotime call_timer;
uint64_t client_old_flags = c->flags;
struct redisCommand *real_cmd = c->realcmd;
@ -3233,22 +3237,34 @@ void call(client *c, int flags) {
dirty = server.dirty;
incrCommandStatsOnError(NULL, 0);
const long long call_timer = ustime();
/* Update cache time, in case we have nested calls we want to
* update only on the first call*/
if (server.fixed_time_expire++ == 0) {
updateCachedTime(0);
updateCachedTimeWithUs(0,call_timer);
}
server.in_nested_call++;
elapsedStart(&call_timer);
monotime monotonic_start = 0;
if (monotonicGetType() == MONOTONIC_CLOCK_HW)
monotonic_start = getMonotonicUs();
server.in_nested_call++;
c->cmd->proc(c);
const long duration = elapsedUs(call_timer);
server.in_nested_call--;
/* In order to avoid performance implication due to querying the clock using a system call 3 times,
* we use a monotonic clock, when we are sure its cost is very low, and fall back to non-monotonic call otherwise. */
ustime_t duration;
if (monotonicGetType() == MONOTONIC_CLOCK_HW)
duration = getMonotonicUs() - monotonic_start;
else
duration = ustime() - call_timer;
c->duration = duration;
dirty = server.dirty-dirty;
if (dirty < 0) dirty = 0;
server.in_nested_call--;
/* Update failed command calls if required. */
if (!incrCommandStatsOnError(real_cmd, ERROR_COMMAND_FAILED) && c->deferred_reply_errors) {
@ -5135,6 +5151,7 @@ sds genRedisInfoString(dict *section_dict, int all_sections, int everything) {
"redis_mode:%s\r\n"
"os:%s %s %s\r\n"
"arch_bits:%i\r\n"
"monotonic_clock:%s\r\n"
"multiplexing_api:%s\r\n"
"atomicvar_api:%s\r\n"
"gcc_version:%i.%i.%i\r\n"
@ -5158,6 +5175,7 @@ sds genRedisInfoString(dict *section_dict, int all_sections, int everything) {
mode,
name.sysname, name.release, name.machine,
server.arch_bits,
monotonicInfoString(),
aeGetApiName(),
REDIS_ATOMIC_API,
#ifdef __GNUC__