Use cached time in expireCommand()

Should not be an issue given that the precision is the second here, at
least if we are using a decent HZ value and the cached time refreshes
enough times. So the cached time is only used if HZ is >= 10.

src/db.c

@@ -862,7 +862,21 @@ int expireIfNeeded(redisDb *db, robj *key) {
      * only the first time it is accessed and not in the middle of the
      * script execution, making propagation to slaves / AOF consistent.
      * See issue #1525 on Github for more information. */
-    now = server.lua_caller ? server.lua_time_start : mstime();
+    if (server.lua_caller) {
+        now = server.lua_time_start;
+    } else {
+        /* If this is not the Lua caller, we actually need to get the current
+         * time. However gettimeofday(), which is called by mstime(), may be
+         * expensive, so we try to use the cached time instead, as found in
+         * server.mstime, which is not very accurate, but should usually be
+         * in the range of +/- 100 milliseconds.
+         *
+         * If the time the key will expire seems to be much more in the future
+         * compared to server.mstime, we use the server.mstime approximation.
+         * Otherwise if we see the key is going to expire within two seconds
+         * we fetch the actual time from the operating system. */
+        now = (when - server.mstime > 2000) ? server.mstime : mstime();
+    }
 
     /* If we are running in the context of a slave, return ASAP:
      * the slave key expiration is controlled by the master that will
@@ -942,7 +956,8 @@ void expireGenericCommand(redisClient *c, long long basetime, int unit) {
 }
 
 void expireCommand(redisClient *c) {
-    expireGenericCommand(c,mstime(),UNIT_SECONDS);
+    long long now = server.hz >= 10 ? server.mstime: mstime();
+    expireGenericCommand(c,now,UNIT_SECONDS);
 }
 
 void expireatCommand(redisClient *c) {

src/multi.c

@@ -162,6 +162,10 @@ void execCommand(redisClient *c) {
         c->mstate.commands[j].argc = c->argc;
         c->mstate.commands[j].argv = c->argv;
         c->mstate.commands[j].cmd = c->cmd;
+
+        /* From time to time, update the cached time so that if the transaction
+         * is huge, we'll have a chance to have more updated time info. */
+        if (j && j % 10000) updateCachedTime();
     }
     c->argv = orig_argv;
     c->argc = orig_argc;

src/redis.c

@@ -766,6 +766,7 @@ void activeExpireCycle(int type) {
     int j, iteration = 0;
     int dbs_per_call = REDIS_DBCRON_DBS_PER_CALL;
     long long start = ustime(), timelimit;
+    long long now = start/1000;
 
     if (type == ACTIVE_EXPIRE_CYCLE_FAST) {
         /* Don't start a fast cycle if the previous cycle did not exited
@@ -810,7 +811,7 @@ void activeExpireCycle(int type) {
          * of the keys were expired. */
         do {
             unsigned long num, slots;
-            long long now, ttl_sum;
+            long long ttl_sum;
             int ttl_samples;
 
             /* If there is nothing to expire try next DB ASAP. */
@@ -819,7 +820,6 @@ void activeExpireCycle(int type) {
                 break;
             }
             slots = dictSlots(db->expires);
-            now = mstime();
 
             /* When there are less than 1% filled slots getting random
              * keys is expensive, so stop here waiting for better times...
@@ -862,7 +862,9 @@ void activeExpireCycle(int type) {
              * caller waiting for the other active expire cycle. */
             iteration++;
             if ((iteration & 0xf) == 0) { /* check once every 16 iterations. */
-                long long elapsed = ustime()-start;
+                now = ustime();
+                long long elapsed = now-start;
+                now /= 1000; /* We need now in milliseconds within the loop. */
 
                 latencyAddSampleIfNeeded("expire-cycle",elapsed/1000);
                 if (elapsed > timelimit) timelimit_exit = 1;
@@ -1554,6 +1556,7 @@ void initServerConfig(void) {
     server.assert_line = 0;
     server.bug_report_start = 0;
     server.watchdog_period = 0;
+    server.use_cmd_time_accounting = 0; /* XXX: this should be configurable. */
 }
 
 /* This function will try to raise the max number of open files accordingly to
@@ -2071,6 +2074,9 @@ void preventCommandPropagation(redisClient *c) {
 /* Call() is the core of Redis execution of a command */
 void call(redisClient *c, int flags) {
     long long dirty, start, duration;
+    int get_duration = server.latency_monitor_threshold != 0 ||
+                       server.slowlog_log_slower_than != 0 ||
+                       server.use_cmd_time_accounting != 0;
     int client_old_flags = c->flags;
 
     /* Sent the command to clients in MONITOR mode, only if the commands are
@@ -2086,9 +2092,9 @@ void call(redisClient *c, int flags) {
     c->flags &= ~(REDIS_FORCE_AOF|REDIS_FORCE_REPL);
     redisOpArrayInit(&server.also_propagate);
     dirty = server.dirty;
-    start = ustime();
+    if (get_duration) start = ustime();
     c->cmd->proc(c);
-    duration = ustime()-start;
+    if (get_duration) duration = ustime()-start;
     dirty = server.dirty-dirty;
     if (dirty < 0) dirty = 0;
 
@@ -2109,14 +2115,18 @@ void call(redisClient *c, int flags) {
 
     /* Log the command into the Slow log if needed, and populate the
      * per-command statistics that we show in INFO commandstats. */
-    if (flags & REDIS_CALL_SLOWLOG && c->cmd->proc != execCommand) {
+    if (get_duration &&
+        flags & REDIS_CALL_SLOWLOG &&
+        c->cmd->proc != execCommand)
+    {
         char *latency_event = (c->cmd->flags & REDIS_CMD_FAST) ?
                               "fast-command" : "command";
         latencyAddSampleIfNeeded(latency_event,duration/1000);
         slowlogPushEntryIfNeeded(c->argv,c->argc,duration);
     }
+
     if (flags & REDIS_CALL_STATS) {
-        c->cmd->microseconds += duration;
+        if (server.use_cmd_time_accounting) c->cmd->microseconds += duration;
         c->cmd->calls++;
     }
 

src/redis.h

@@ -732,6 +732,7 @@ struct redisServer {
     size_t resident_set_size;       /* RSS sampled in serverCron(). */
     long long stat_net_input_bytes; /* Bytes read from network. */
     long long stat_net_output_bytes; /* Bytes written to network. */
+    int use_cmd_time_accounting;     /* commandstats time accounting. */
     /* The following two are used to track instantaneous metrics, like
      * number of operations per second, network traffic. */
     struct {

src/scripting.c

@@ -546,7 +546,8 @@ void luaMaskCountHook(lua_State *lua, lua_Debug *ar) {
     REDIS_NOTUSED(ar);
     REDIS_NOTUSED(lua);
 
-    elapsed = mstime() - server.lua_time_start;
+    updateCachedTime();
+    elapsed = server.mstime - server.lua_time_start;
     if (elapsed >= server.lua_time_limit && server.lua_timedout == 0) {
         redisLog(REDIS_WARNING,"Lua slow script detected: still in execution after %lld milliseconds. You can try killing the script using the SCRIPT KILL command.",elapsed);
         server.lua_timedout = 1;