diff --git a/frontend/apps/reader/readerui.lua b/frontend/apps/reader/readerui.lua index ad9eb8f8a..5c84c12fd 100644 --- a/frontend/apps/reader/readerui.lua +++ b/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)) diff --git a/frontend/document/credocument.lua b/frontend/document/credocument.lua index ba6679a96..67990cdb2 100644 --- a/frontend/document/credocument.lua +++ b/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() - --print(string.format("CreDocument:drawCurrentView: Rendering took %9.3f ms", (end_ts - start_ts) * 1000)) + --local end_tv = TimeVal:now() + --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() - --print(string.format("CreDocument:drawCurrentView: Blitting took %9.3f ms", (end_ts - start_ts) * 1000)) + --end_tv = TimeVal:now() + --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 - if not duration then duration = 0.0 end + local duration = TimeVal:getDuration(starttime) 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) diff --git a/frontend/ui/timeval.lua b/frontend/ui/timeval.lua index 3948f721e..90b6b2351 100644 --- a/frontend/ui/timeval.lua +++ b/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 diff --git a/plugins/calibre.koplugin/metadata.lua b/plugins/calibre.koplugin/metadata.lua index 0b2c6925f..eba130ec0 100644 --- a/plugins/calibre.koplugin/metadata.lua +++ b/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 diff --git a/plugins/calibre.koplugin/search.lua b/plugins/calibre.koplugin/search.lua index 6f3e30909..45299f5d9 100644 --- a/plugins/calibre.koplugin/search.lua +++ b/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 diff --git a/plugins/coverbrowser.koplugin/bookinfomanager.lua b/plugins/coverbrowser.koplugin/bookinfomanager.lua index 8e9dc839c..c279c4cbb 100644 --- a/plugins/coverbrowser.koplugin/bookinfomanager.lua +++ b/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_killall_timeout_seconds = 300 -- cleanup timeout for stuck subprocesses - -- 300 seconds should be enough to open and get info from 9-10 books + self.subprocesses_last_added_tv = TimeVal.zero + self.subprocesses_killall_timeout_tv = TimeVal:new{ sec = 300, usec = 0 } -- cleanup timeout for stuck subprocesses + -- 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)