debug stats logging

Author: jason-famedly

synapse/app/phone_stats_home.py

@@ -118,13 +118,34 @@ async def _phone_stats_home(
         stats["memory_rss"] = new[1].ru_maxrss
 
         # Get CPU time in % of a single core, not % of all cores
+        logger.info("Calculating used_cpu_time")
+        logger.info(
+            "new_cpu_time: %r + %r = %r",
+            new[1].ru_utime,
+            new[1].ru_stime,
+            new[1].ru_utime + new[1].ru_stime,
+        )
+        logger.info(
+            "old_cpu_time: %r + %r = %r",
+            old[1].ru_utime,
+            old[1].ru_stime,
+            old[1].ru_utime + old[1].ru_stime,
+        )
+        logger.info(
+            "difference: %r",
+            (new[1].ru_utime + new[1].ru_stime) - (old[1].ru_utime + old[1].ru_stime),
+        )
         used_cpu_time = (new[1].ru_utime + new[1].ru_stime) - (
             old[1].ru_utime + old[1].ru_stime
         )
         if used_cpu_time == 0 or new[0] == old[0]:
             stats["cpu_average"] = 0
         else:
-            stats["cpu_average"] = math.floor(used_cpu_time / (new[0] - old[0]) * 100)
+            time_diff = new[0] - old[0]
+            logger.info("time_diff: %r ", time_diff)
+            the_number = math.floor(used_cpu_time / time_diff) * 100
+            logger.info("calculated cpu time: %r", the_number)
+            stats["cpu_average"] = the_number
 
         #
         # General statistics

tests/test_phone_home.py

@@ -31,7 +31,7 @@
 from synapse.types import JsonDict
 from synapse.util.clock import Clock
 
-from tests.unittest import HomeserverTestCase
+from tests.unittest import DEBUG, HomeserverTestCase
 
 
 class PhoneHomeStatsTestCase(HomeserverTestCase):
@@ -46,13 +46,14 @@ def test_performance_frozen_clock(self) -> None:
         self.get_success(phone_stats_home(self.hs, stats, past_stats))
         self.assertEqual(stats["cpu_average"], 0)
 
+    @DEBUG
     def test_performance_100(self) -> None:
         """
         1 second of usage over 1 second is 100% CPU usage.
         """
         real_res = resource.getrusage(resource.RUSAGE_SELF)
         old_resource = mock.Mock(spec=real_res)
-        old_resource.ru_utime = real_res.ru_utime - 1
+        old_resource.ru_utime = real_res.ru_utime
         old_resource.ru_stime = real_res.ru_stime
         old_resource.ru_maxrss = real_res.ru_maxrss