Port ffiUtil.getTimestamp users to TimeVal:now()

They were all using it to compute durations,
something which is going to be more sensible
from a monotonic clock source.

frontend/apps/reader/readerui.lua

@@ -52,6 +52,7 @@ local ReaderWikipedia = require("apps/reader/modules/readerwikipedia")
 local ReaderZooming = require("apps/reader/modules/readerzooming")
 local Screenshoter = require("ui/widget/screenshoter")
 local SettingsMigration = require("ui/data/settings_migration")
+local TimeVal = require("ui/timeval")
 local UIManager = require("ui/uimanager")
 local ffiUtil  = require("ffi/util")
 local lfs = require("libs/libkoreader-lfs")
@@ -277,19 +278,19 @@ function ReaderUI:init()
         end
         -- make sure we render document first before calling any callback
         self:registerPostInitCallback(function()
-            local start_ts = ffiUtil.getTimestamp()
+            local start_tv = TimeVal:now()
             if not self.document:loadDocument() then
                 self:dealWithLoadDocumentFailure()
             end
-            logger.dbg(string.format("  loading took %.3f seconds", ffiUtil.getDuration(start_ts)))
+            logger.dbg(string.format("  loading took %.3f seconds", TimeVal:getDuration(start_tv)))
 
             -- used to read additional settings after the document has been
             -- loaded (but not rendered yet)
             self:handleEvent(Event:new("PreRenderDocument", self.doc_settings))
 
-            start_ts = ffiUtil.getTimestamp()
+            start_tv = TimeVal:now()
             self.document:render()
-            logger.dbg(string.format("  rendering took %.3f seconds", ffiUtil.getDuration(start_ts)))
+            logger.dbg(string.format("  rendering took %.3f seconds", TimeVal:getDuration(start_tv)))
 
             -- Uncomment to output the built DOM (for debugging)
             -- logger.dbg(self.document:getHTMLFromXPointer(".0", 0x6830))

frontend/document/credocument.lua

@@ -2,11 +2,11 @@ local Blitbuffer = require("ffi/blitbuffer")
 local CanvasContext = require("document/canvascontext")
 local DataStorage = require("datastorage")
 local Document = require("document/document")
-local FFIUtil = require("ffi/util")
 local FontList = require("fontlist")
 local Geom = require("ui/geometry")
 local RenderImage = require("ui/renderimage")
 local Screen = require("device").screen
+local TimeVal = require("ui/timeval")
 local ffi = require("ffi")
 local C = ffi.C
 local lfs = require("libs/libkoreader-lfs")
@@ -690,16 +690,16 @@ function CreDocument:drawCurrentView(target, x, y, rect, pos)
     -- We also honor the current smooth scaling setting,
     -- as well as the global SW dithering setting.
 
-    --local start_ts = FFIUtil.getTimestamp()
+    --local start_tv = TimeVal:now()
     self._drawn_images_count, self._drawn_images_surface_ratio =
         self._document:drawCurrentPage(self.buffer, self.render_color, Screen.night_mode and self._nightmode_images, self._smooth_scaling, Screen.sw_dithering)
-    --local end_ts = FFIUtil.getTimestamp()
+    --local end_tv = TimeVal:now()
-    --print(string.format("CreDocument:drawCurrentView: Rendering took %9.3f ms", (end_ts - start_ts) * 1000))
+    --print(string.format("CreDocument:drawCurrentView: Rendering took %9.3f ms", (end_tv - start_tv):tomsecs()))
 
-    --start_ts = FFIUtil.getTimestamp()
+    --start_tv = TimeVal:now()
     target:blitFrom(self.buffer, x, y, 0, 0, rect.w, rect.h)
-    --end_ts = FFIUtil.getTimestamp()
+    --end_tv = TimeVal:now()
-    --print(string.format("CreDocument:drawCurrentView: Blitting took  %9.3f ms", (end_ts - start_ts) * 1000))
+    --print(string.format("CreDocument:drawCurrentView: Blitting took  %9.3f ms", (end_tv - start_tv):tomsecs()))
 end
 
 function CreDocument:drawCurrentViewByPos(target, x, y, rect, pos)
@@ -1447,7 +1447,7 @@ function CreDocument:setupCallCache()
         -- cache statistics
         self._call_cache_stats = {}
         addStatMiss = function(name, starttime, not_cached)
-            local duration = FFIUtil.getTimestamp() - starttime
+            local duration = TimeVal:getDuration(starttime)
             if not self._call_cache_stats[name] then
                 self._call_cache_stats[name] = {0, 0.0, 1, duration, not_cached}
             else
@@ -1457,8 +1457,7 @@ function CreDocument:setupCallCache()
             end
         end
         addStatHit = function(name, starttime)
-            local duration = FFIUtil.getTimestamp() - starttime
+            local duration = TimeVal:getDuration(starttime)
-            if not duration then duration = 0.0 end
             if not self._call_cache_stats[name] then
                 self._call_cache_stats[name] = {1, duration, 0, 0.0}
             else
@@ -1538,7 +1537,7 @@ function CreDocument:setupCallCache()
                     total_duration = total_duration + missed_duration + hits_duration
                 end
             end
-            local pct_duration_saved = 100.0 * total_duration_saved / (total_duration+total_duration_saved)
+            local pct_duration_saved = 100.0 * total_duration_saved / (total_duration + total_duration_saved)
             table.insert(res, string.format("  cpu time used: %.3fs, saved: %.3fs (%d%% saved)", total_duration, total_duration_saved, pct_duration_saved))
             return table.concat(res, "\n")
         end
@@ -1668,7 +1667,7 @@ function CreDocument:setupCallCache()
             elseif cache_by_tag then
                 is_cached = true
                 self[name] = function(...)
-                    local starttime = FFIUtil.getTimestamp()
+                    local starttime = TimeVal:now()
                     local cache_key = name .. asString(select(2, ...))
                     local results = self._callCacheTagGet(cache_key)
                     if results then
@@ -1689,7 +1688,7 @@ function CreDocument:setupCallCache()
             elseif cache_global then
                 is_cached = true
                 self[name] = function(...)
-                    local starttime = FFIUtil.getTimestamp()
+                    local starttime = TimeVal:now()
                     local cache_key = name .. asString(select(2, ...))
                     local results = self._callCacheGet(cache_key)
                     if results then
@@ -1709,7 +1708,7 @@ function CreDocument:setupCallCache()
             if do_stats_include_not_cached and not is_cached then
                 local func2 = self[name] -- might already be wrapped
                 self[name] = function(...)
-                    local starttime = FFIUtil.getTimestamp()
+                    local starttime = TimeVal:now()
                     local results = { func2(...) }
                     addStatMiss(name, starttime, true) -- not_cached = true
                     return unpack(results)
@@ -1731,7 +1730,7 @@ function CreDocument:setupCallCache()
         elseif current_buffer_tag ~= current_tag then
             do_draw = true
         end
-        local starttime = FFIUtil.getTimestamp()
+        local starttime = TimeVal:now()
         if do_draw then
             if do_log then logger.dbg("callCache: ########## drawCurrentView: full draw") end
             CreDocument.drawCurrentView(_self, target, x, y, rect, pos)

frontend/ui/timeval.lua

@@ -238,6 +238,30 @@ function TimeVal:fromnumber(seconds)
     return TimeVal:new{ sec = sec, usec = usec }
 end
 
+--[[-- Compare a past *MONOTONIC* TimeVal object to *now*, returning the elapsed time between the two. (sec.usecs variant)
+
+Returns a Lua (decimal) number (sec.usecs) (accurate to the ms, rounded to 4 decimal places) (i.e., :tonumber())
+]]
+function TimeVal:getDuration(start_tv)
+   return (TimeVal:now() - start_tv):tonumber()
+end
+
+--[[-- Compare a past *MONOTONIC* TimeVal object to *now*, returning the elapsed time between the two. (µs variant)
+
+Returns a Lua (int) number (resolution: 1µs) (i.e., :tousecs())
+]]
+function TimeVal:getDurationUs(start_tv)
+   return (TimeVal:now() - start_tv):tousecs()
+end
+
+--[[-- Compare a past *MONOTONIC* TimeVal object to *now*, returning the elapsed time between the two. (ms variant)
+
+Returns a Lua (int) number (resolution: 1ms) (i.e., :tomsecs())
+]]
+function TimeVal:getDurationMs(start_tv)
+   return (TimeVal:now() - start_tv):tomsecs()
+end
+
 --- Checks if a TimeVal object is positive
 function TimeVal:isPositive()
     return self.sec >= 0

plugins/calibre.koplugin/metadata.lua

@@ -261,12 +261,12 @@ function CalibreMetadata:init(dir, is_search)
     if is_search then
         self:cleanUnused(is_search)
         msg = string.format("(search) in %.3f milliseconds: %d books",
-            (TimeVal:now() - start):tomsecs(), #self.books)
+            TimeVal:getDurationMs(start), #self.books)
     else
         local deleted_count = self:prune()
         self:cleanUnused()
         msg = string.format("in %.3f milliseconds: %d books. %d pruned",
-            (TimeVal:now() - start):tomsecs(), #self.books, deleted_count)
+            TimeVal:getDurationMs(start), #self.books, deleted_count)
     end
     logger.info(string.format("calibre info loaded from disk %s", msg))
     return true

plugins/calibre.koplugin/search.lua

@@ -338,7 +338,7 @@ function CalibreSearch:find(option)
         self:browse(option, 1)
     end
     logger.info(string.format("search done in %.3f milliseconds (%s, %s, %s, %s, %s)",
-        (TimeVal:now() - start):tomsecs(),
+        TimeVal:getDurationMs(start),
         option == "find" and "books" or option,
         "case sensitive: " .. tostring(not self.case_insensitive),
         "title: " .. tostring(self.find_by_title),
@@ -604,7 +604,7 @@ function CalibreSearch:getMetadata()
                 end
             end
             if is_newer then
-                logger.info(string.format(template, #cache, "cache", (TimeVal:now() - start):tomsecs()))
+                logger.info(string.format(template, #cache, "cache", TimeVal:getDurationMs(start)))
                 return cache
             else
                 logger.warn("cache is older than metadata, ignoring it")
@@ -633,7 +633,7 @@ function CalibreSearch:getMetadata()
             logger.info("Failed to serialize calibre metadata cache:", err)
         end
     end
-    logger.info(string.format(template, #books, "calibre", (TimeVal:now() - start):tomsecs()))
+    logger.info(string.format(template, #books, "calibre", TimeVal:getDurationMs(start)))
     return books
 end
 

plugins/coverbrowser.koplugin/bookinfomanager.lua

@@ -7,6 +7,7 @@ local FFIUtil = require("ffi/util")
 local InfoMessage = require("ui/widget/infomessage")
 local RenderImage = require("ui/renderimage")
 local SQ3 = require("lua-ljsqlite3/init")
+local TimeVal = require("ui/timeval")
 local UIManager = require("ui/uimanager")
 local lfs = require("libs/libkoreader-lfs")
 local logger = require("logger")
@@ -124,9 +125,9 @@ function BookInfoManager:init()
     self.subprocesses_collector = nil
     self.subprocesses_collect_interval = 10 -- do that every 10 seconds
     self.subprocesses_pids = {}
-    self.subprocesses_last_added_ts = nil
+    self.subprocesses_last_added_tv = TimeVal.zero
-    self.subprocesses_killall_timeout_seconds = 300 -- cleanup timeout for stuck subprocesses
+    self.subprocesses_killall_timeout_tv = TimeVal:new{ sec = 300, usec = 0 } -- cleanup timeout for stuck subprocesses
-    -- 300 seconds should be enough to open and get info from 9-10 books
+    -- 300 seconds should be more than enough to open and get info from 9-10 books
     -- Whether to use former blitbuffer:scale() (default to using MuPDF)
     self.use_legacy_image_scaling = G_reader_settings:isTrue("legacy_image_scaling")
     -- We will use a temporary directory for crengine cache while indexing
@@ -643,7 +644,7 @@ function BookInfoManager:collectSubprocesses()
             -- the user has not left FileManager or changed page - that would
             -- have caused a terminateBackgroundJobs() - if we're here, it's
             -- that user has left reader in FileBrower and went away)
-            if FFIUtil.getTimestamp() > self.subprocesses_last_added_ts + self.subprocesses_killall_timeout_seconds then
+            if TimeVal:now() > self.subprocesses_last_added_tv + self.subprocesses_killall_timeout_tv then
                 logger.warn("Some subprocesses were running for too long, killing them")
                 self:terminateBackgroundJobs()
                 -- we'll collect them next time we're run
@@ -707,7 +708,7 @@ function BookInfoManager:extractInBackground(files)
     -- counter on each task, and undo that inside collectSubprocesses() zombie reaper.
     UIManager:preventStandby()
     table.insert(self.subprocesses_pids, task_pid)
-    self.subprocesses_last_added_ts = FFIUtil.getTimestamp()
+    self.subprocesses_last_added_tv = TimeVal:now()
 
     -- We need to collect terminated jobs pids (so they do not stay "zombies"
     -- and fill linux processes table)