From c166620d5f9706e54f9cd67044d42bf8583575d8 Mon Sep 17 00:00:00 2001
From: Krateng <git.noreply@krateng.ch>
Date: Fri, 29 May 2020 16:45:41 +0200
Subject: [PATCH] Properly implemented cache debug logging

---
 maloja/__pkginfo__.py |  2 +-
 maloja/database.py    | 46 +++++++++++++++++++++++--------------------
 maloja/server.py      |  6 +++---
 3 files changed, 29 insertions(+), 25 deletions(-)

diff --git a/maloja/__pkginfo__.py b/maloja/__pkginfo__.py
index 07b3858..1c30f30 100644
--- a/maloja/__pkginfo__.py
+++ b/maloja/__pkginfo__.py
@@ -5,7 +5,7 @@ author = {
 	"email":"maloja@krateng.dev",
 	"github": "krateng"
 }
-version = 2,4,6
+version = 2,4,7
 versionstr = ".".join(str(n) for n in version)
 links = {
 	"pypi":"malojaserver",
diff --git a/maloja/database.py b/maloja/database.py
index 81fba66..dffc987 100644
--- a/maloja/database.py
+++ b/maloja/database.py
@@ -1062,34 +1062,32 @@ cache_aggregate = lru.LRU(csz)
 cache_aggregate_perm = lru.LRU(csz)
 
 cachestats = {
-	"cache_query_tmp":{
-		"obj":cache_query,
-		"hits":0,
-		"misses":0
-	},
-	"cache_query_perm":{
-		"obj":cache_query_perm,
-		"hits":0,
-		"misses":0
-	},
-	"cache_aggregate_tmp":{
-		"obj":cache_aggregate,
-		"hits":0,
-		"misses":0
-	},
-	"cache_aggregate_perm":{
-		"obj":cache_aggregate_perm,
-		"hits":0,
-		"misses":0
+	"cache_query":{
+		"hits_perm":0,
+		"hits_tmp":0,
+		"misses":0,
+		"objperm":cache_query_perm,
+		"objtmp":cache_query,
+		"name":"Query Cache"
 	},
+	"cache_aggregate":{
+		"hits_perm":0,
+		"hits_tmp":0,
+		"misses":0,
+		"objperm":cache_aggregate_perm,
+		"objtmp":cache_aggregate,
+		"name":"Aggregate Cache"
+	}
 }
 
 from doreah.regular import runhourly
 
 @runhourly
 def log_stats():
-	log({c:{"size":len(cachestats[c]["obj"]),"hits":cachestats[c]["hits"],"misses":cachestats[c]["misses"]} for c in cachestats},module="debug")
-
+	logstr = "{name}: {hitsperm} Perm Hits, {hitstmp} Tmp Hits, {misses} Misses; Current Size: {sizeperm}/{sizetmp}"
+	for s in (cachestats["cache_query"],cachestats["cache_aggregate"]):
+		log(logstr.format(name=s["name"],hitsperm=s["hits_perm"],hitstmp=s["hits_tmp"],misses=s["misses"],
+		sizeperm=len(s["objperm"]),sizetmp=len(s["objtmp"])))
 
 def db_query_cached(**kwargs):
 	global cache_query, cache_query_perm
@@ -1107,13 +1105,16 @@ def db_query_cached(**kwargs):
 
 	# hit permanent cache for past timeranges
 	if eligible_permanent_caching and key in cache_query_perm:
+		cachestats["cache_query"]["hits_perm"] += 1
 		return copy.copy(cache_query_perm.get(key))
 
 	# hit short term cache
 	elif eligible_temporary_caching and key in cache_query:
+		cachestats["cache_query"]["hits_tmp"] += 1
 		return copy.copy(cache_query.get(key))
 
 	else:
+		cachestats["cache_query"]["misses"] += 1
 		result = db_query_full(**kwargs)
 		if eligible_permanent_caching: cache_query_perm[key] = result
 		elif eligible_temporary_caching: cache_query[key] = result
@@ -1136,13 +1137,16 @@ def db_aggregate_cached(**kwargs):
 
 	# hit permanent cache for past timeranges
 	if eligible_permanent_caching and key in cache_aggregate_perm:
+		cachestats["cache_aggregate"]["hits_perm"] += 1
 		return copy.copy(cache_aggregate_perm.get(key))
 
 	# hit short term cache
 	elif eligible_temporary_caching and key in cache_aggregate:
+		cachestats["cache_aggregate"]["hits_tmp"] += 1
 		return copy.copy(cache_aggregate.get(key))
 
 	else:
+		cachestats["cache_aggregate"]["misses"] += 1
 		result = db_aggregate_full(**kwargs)
 		if eligible_permanent_caching: cache_aggregate_perm[key] = result
 		elif eligible_temporary_caching: cache_aggregate[key] = result
diff --git a/maloja/server.py b/maloja/server.py
index 176a47c..51eb690 100755
--- a/maloja/server.py
+++ b/maloja/server.py
@@ -245,7 +245,7 @@ def static_html(name):
 		template = jinjaenv.get_template(name + '.jinja')
 
 		res = template.render(**LOCAL_CONTEXT)
-		log("Generated page {name} in {time}s (Jinja)".format(name=name,time=clock.stop()),module="debug")
+		log("Generated page {name} in {time:.5f}s (Jinja)".format(name=name,time=clock.stop()),module="debug")
 		return res
 
 	# if a pyhp file exists, use this
@@ -272,7 +272,7 @@ def static_html(name):
 
 		#response.set_header("Content-Type","application/xhtml+xml")
 		res = pyhpfile(pthjoin(WEBFOLDER,"pyhp",name + ".pyhp"),environ)
-		log("Generated page {name} in {time}s (PYHP)".format(name=name,time=clock.stop()),module="debug")
+		log("Generated page {name} in {time:.5f}s (PYHP)".format(name=name,time=clock.stop()),module="debug")
 		return res
 
 	# if not, use the old way
@@ -316,7 +316,7 @@ def static_html(name):
 
 
 		response.set_header("Link",",".join(linkheaders))
-		log("Generated page " + name + " in " + str(clock.stop()) + "s (Python+HTML)",module="debug")
+		log("Generated page {name} in {time:.5f}s (Python+HTML)".format(name=name,time=clock.stop()),module="debug")
 		return html
 		#return static_file("web/" + name + ".html",root="")