made spammy timing logs require BA_DEBUG_TIMING=1 env var

2026-01-23 07:23:19 +08:00 · 2022-07-08 12:15:37 -07:00 · 2022-07-08 12:15:37 -07:00 · fa3db1e3ca
commit fa3db1e3ca
parent 80a132ec7d
10 changed files with 68 additions and 48 deletions
--- a/.efrocachemap
+++ b/.efrocachemap
@ -3995,26 +3995,26 @@
  "assets/src/ba_data/python/ba/_generated/__init__.py": "https://files.ballistica.net/cache/ba1/ee/e8/cad05aa531c7faf7ff7b96db7f6e",
  "assets/src/ba_data/python/ba/_generated/enums.py": "https://files.ballistica.net/cache/ba1/b2/e5/0ee0561e16257a32830645239f34",
  "ballisticacore-windows/Generic/BallisticaCore.ico": "https://files.ballistica.net/cache/ba1/89/c0/e32c7d2a35dc9aef57cc73b0911a",
-  "build/prefab/full/linux_arm64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/1a/39/acfbc22a3b5c42fc8d7041c39d69",
-  "build/prefab/full/linux_arm64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/32/13/b2fb8f259bbd899789108036bae9",
-  "build/prefab/full/linux_arm64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/c0/82/b986c8348b474e3299d4aac7bc32",
-  "build/prefab/full/linux_arm64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/48/39/3978b186f6db8e0fd01c250868b7",
-  "build/prefab/full/linux_x86_64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/4f/1e/17ffb859868e36203dc9286a4434",
-  "build/prefab/full/linux_x86_64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/77/77/6671c0637457b48041711daf27da",
-  "build/prefab/full/linux_x86_64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/18/82/776af0c81fb17839b7b8bc264012",
-  "build/prefab/full/linux_x86_64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/1c/cf/75b00bce2ce670a5c95af086d9a0",
-  "build/prefab/full/mac_arm64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/8a/35/ff23ca37f42b0bfa6ca159630fe4",
-  "build/prefab/full/mac_arm64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/9b/5f/904c100c7c5646c7331cb26b8db6",
-  "build/prefab/full/mac_arm64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/89/9d/0aacb629f5dc8fd10ce55debbe79",
-  "build/prefab/full/mac_arm64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/5c/ea/0f158f114b2b3d0a534aebfeaebf",
-  "build/prefab/full/mac_x86_64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/f3/4c/06b71f58c5b03454b61360e8591b",
-  "build/prefab/full/mac_x86_64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/72/4a/de64093c85f32f5dbba5389da90c",
-  "build/prefab/full/mac_x86_64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/14/e0/9c9088bd9db01969bf1a1e838dda",
-  "build/prefab/full/mac_x86_64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/7c/39/05b1d3873ca9f1d6a7b904732630",
-  "build/prefab/full/windows_x86_gui/debug/BallisticaCore.exe": "https://files.ballistica.net/cache/ba1/1c/cb/2a1576774e2ac14fed571d1d3232",
-  "build/prefab/full/windows_x86_gui/release/BallisticaCore.exe": "https://files.ballistica.net/cache/ba1/df/0a/0284198f2802439349515c8b83f2",
-  "build/prefab/full/windows_x86_server/debug/dist/BallisticaCoreHeadless.exe": "https://files.ballistica.net/cache/ba1/63/66/c6fa125299b8dc26887a0e5c5f58",
-  "build/prefab/full/windows_x86_server/release/dist/BallisticaCoreHeadless.exe": "https://files.ballistica.net/cache/ba1/01/dd/d5d189b16974b6314ba76584b7b2",
+  "build/prefab/full/linux_arm64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/b4/6b/d57bf44327be5c7cd5ab469b0f73",
+  "build/prefab/full/linux_arm64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/6b/8a/e15c3d97afa4e888da708a4eedb4",
+  "build/prefab/full/linux_arm64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/ae/90/efe160ebfe1a6fac7474d43848e3",
+  "build/prefab/full/linux_arm64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/57/79/e1ad4d39d1e39623add63f9cf305",
+  "build/prefab/full/linux_x86_64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/cf/14/9265e972e27bbb406b5ca90a3331",
+  "build/prefab/full/linux_x86_64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/17/8c/303ff3d19255162ca4ee44d17f14",
+  "build/prefab/full/linux_x86_64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/97/6d/b0225caf7d1bf38dfd7320a7837f",
+  "build/prefab/full/linux_x86_64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/62/c4/6b53ea09f6c81fa1056c1bf6b2b3",
+  "build/prefab/full/mac_arm64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/ff/07/0a1007b66e498a0ca6e2764dbdc4",
+  "build/prefab/full/mac_arm64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/9d/35/6a2254dc00e6d2207656ea08639b",
+  "build/prefab/full/mac_arm64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/ad/ea/4d49c0e06db1863153e63c155381",
+  "build/prefab/full/mac_arm64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/e9/73/c927d2380d2e33929a55efdf8403",
+  "build/prefab/full/mac_x86_64_gui/debug/ballisticacore": "https://files.ballistica.net/cache/ba1/0a/e8/a69ae8672182b64e33fc1faea7a1",
+  "build/prefab/full/mac_x86_64_gui/release/ballisticacore": "https://files.ballistica.net/cache/ba1/80/09/f1b52871804107f77502a5a12692",
+  "build/prefab/full/mac_x86_64_server/debug/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/33/79/fcf389e566ae93609a0b45c6f280",
+  "build/prefab/full/mac_x86_64_server/release/dist/ballisticacore_headless": "https://files.ballistica.net/cache/ba1/27/2b/b3e6e2c60499942516e74c790463",
+  "build/prefab/full/windows_x86_gui/debug/BallisticaCore.exe": "https://files.ballistica.net/cache/ba1/e3/46/c7c92b5037e8db89c8e91d498bab",
+  "build/prefab/full/windows_x86_gui/release/BallisticaCore.exe": "https://files.ballistica.net/cache/ba1/df/d0/ef6344d54ec119ad332c7b50fef9",
+  "build/prefab/full/windows_x86_server/debug/dist/BallisticaCoreHeadless.exe": "https://files.ballistica.net/cache/ba1/ae/1a/4f9399f80f681218710a3ae47cd8",
+  "build/prefab/full/windows_x86_server/release/dist/BallisticaCoreHeadless.exe": "https://files.ballistica.net/cache/ba1/87/5d/ab4b1886fa00acca24ae525af0b7",
  "build/prefab/lib/linux_arm64_gui/debug/libballisticacore_internal.a": "https://files.ballistica.net/cache/ba1/95/cf/7c343cd320548f535b75b5993275",
  "build/prefab/lib/linux_arm64_gui/release/libballisticacore_internal.a": "https://files.ballistica.net/cache/ba1/a5/ee/8c89b68c2b26464768335e4c3361",
  "build/prefab/lib/linux_arm64_server/debug/libballisticacore_internal.a": "https://files.ballistica.net/cache/ba1/18/93/76a49888f17ea1677b9b49244416",
@ -4031,14 +4031,14 @@
  "build/prefab/lib/mac_x86_64_gui/release/libballisticacore_internal.a": "https://files.ballistica.net/cache/ba1/ae/bb/4a015a49120e908a6d17f302d0d8",
  "build/prefab/lib/mac_x86_64_server/debug/libballisticacore_internal.a": "https://files.ballistica.net/cache/ba1/e2/ff/1b0c530cbba73a0ea895a56626b6",
  "build/prefab/lib/mac_x86_64_server/release/libballisticacore_internal.a": "https://files.ballistica.net/cache/ba1/9c/8e/53fdfaf4f5113970e2aefcb6a06e",
-  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreGenericInternal.lib": "https://files.ballistica.net/cache/ba1/70/5a/bab38dcc254aeba112894ee278cd",
-  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreGenericInternal.pdb": "https://files.ballistica.net/cache/ba1/ac/31/ce9ba1b80db55b753626d3053898",
-  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreHeadlessInternal.lib": "https://files.ballistica.net/cache/ba1/32/5e/3c919d17f772a5bd1192a9ac3eda",
-  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreHeadlessInternal.pdb": "https://files.ballistica.net/cache/ba1/28/2b/9b48b6805ee243f2813d5f0359e8",
-  "build/prefab/lib/windows/Release_Win32/BallisticaCoreGenericInternal.lib": "https://files.ballistica.net/cache/ba1/bd/2a/8627c6f6938bc46a4fca7a033ab3",
-  "build/prefab/lib/windows/Release_Win32/BallisticaCoreGenericInternal.pdb": "https://files.ballistica.net/cache/ba1/54/63/15a0d31548d76237c65529d3bf99",
-  "build/prefab/lib/windows/Release_Win32/BallisticaCoreHeadlessInternal.lib": "https://files.ballistica.net/cache/ba1/2d/d4/e7fb6077712e4267a4d64529e005",
-  "build/prefab/lib/windows/Release_Win32/BallisticaCoreHeadlessInternal.pdb": "https://files.ballistica.net/cache/ba1/55/44/83e93c9d77ffd2589e7a8795b212",
+  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreGenericInternal.lib": "https://files.ballistica.net/cache/ba1/72/67/a7e5168376965df78b1b1716b76d",
+  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreGenericInternal.pdb": "https://files.ballistica.net/cache/ba1/56/67/e7b64f45bc15fe309e0082192179",
+  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreHeadlessInternal.lib": "https://files.ballistica.net/cache/ba1/e1/71/a7f5590a057b3b9d5e421ca3ff43",
+  "build/prefab/lib/windows/Debug_Win32/BallisticaCoreHeadlessInternal.pdb": "https://files.ballistica.net/cache/ba1/b1/73/06806075931d4939b10dd70a93e4",
+  "build/prefab/lib/windows/Release_Win32/BallisticaCoreGenericInternal.lib": "https://files.ballistica.net/cache/ba1/61/8c/06ec6a9974aedd5ac58ee55a1d98",
+  "build/prefab/lib/windows/Release_Win32/BallisticaCoreGenericInternal.pdb": "https://files.ballistica.net/cache/ba1/b9/9c/8b4f1842127ffda670c4b343b153",
+  "build/prefab/lib/windows/Release_Win32/BallisticaCoreHeadlessInternal.lib": "https://files.ballistica.net/cache/ba1/d7/4e/d3429d4b1fbf6f62ab21db7d441d",
+  "build/prefab/lib/windows/Release_Win32/BallisticaCoreHeadlessInternal.pdb": "https://files.ballistica.net/cache/ba1/fb/c5/d72dd63187f7e90051794bcc6bf2",
  "src/ballistica/generated/python_embedded/binding.inc": "https://files.ballistica.net/cache/ba1/6e/6f/004b696e9a13b083069374e4bb6a",
  "src/ballistica/generated/python_embedded/bootstrap.inc": "https://files.ballistica.net/cache/ba1/d3/db/e73d4dcf1280d5f677c3cf8b47c3"
 }
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@ -1,8 +1,9 @@
-### 1.7.4 (20638, 2022-07-07)
+### 1.7.4 (20641, 2022-07-08)
 - Fixed the trophies list showing an incorrect total (Thanks itsre3!)
 - ba.app.meta.metascan is now ba.app.meta.scanresults
 - Cleaned up co-op ui code a bit
 - Added a utility function to add custom co-op games in the practice section: `ba.app.add_coop_practice_level`. Also added new workspace template script which uses it to define a new co-op game type.
+- Removed some spammy debug timing logging I added for tracking down a recent bug (can be reenabled by setting env var `BA_DEBUG_TIMING=1`)

 ### 1.7.3 (20634, 2022-07-06)
 - Fixed an issue with King of the Hill flag regions not working when players entered them (Thanks itsre3!)
--- a/assets/src/ba_data/python/._ba_sources_hash
+++ b/assets/src/ba_data/python/._ba_sources_hash
@ -1 +1 @@
-278132313134406072250536815637474504399
+162333092055412382592908646337833811891
--- a/assets/src/ba_data/python/ba/_asyncio.py
+++ b/assets/src/ba_data/python/ba/_asyncio.py
@ -13,6 +13,7 @@ from typing import TYPE_CHECKING
 import asyncio
 import logging
 import time
+import os

 if TYPE_CHECKING:
    import ba
@ -21,6 +22,8 @@ if TYPE_CHECKING:
 _asyncio_timer: ba.Timer | None = None
 _asyncio_event_loop: asyncio.AbstractEventLoop | None = None

+DEBUG_TIMING = os.environ.get('BA_DEBUG_TIMING') == '1'
+

 def setup_asyncio() -> asyncio.AbstractEventLoop:
    """Setup asyncio functionality for the logic thread."""
@ -55,16 +58,18 @@ def setup_asyncio() -> asyncio.AbstractEventLoop:
    def run_cycle() -> None:
        assert _asyncio_event_loop is not None
        _asyncio_event_loop.call_soon(_asyncio_event_loop.stop)
-        starttime = time.monotonic()
+        starttime = time.monotonic() if DEBUG_TIMING else 0
        _asyncio_event_loop.run_forever()
-        endtime = time.monotonic()
+        endtime = time.monotonic() if DEBUG_TIMING else 0

        # Let's aim to have nothing take longer than 1/120 of a second.
-        warn_time = 1.0 / 120
-        duration = endtime - starttime
-        if duration > warn_time:
-            logging.warning('Asyncio loop step took %.4fs; ideal max is %.4f',
-                            duration, warn_time)
+        if DEBUG_TIMING:
+            warn_time = 1.0 / 120
+            duration = endtime - starttime
+            if duration > warn_time:
+                logging.warning(
+                    'Asyncio loop step took %.4fs; ideal max is %.4f',
+                    duration, warn_time)

    global _asyncio_timer  # pylint: disable=invalid-name
    _asyncio_timer = _ba.Timer(1.0 / 30.0,
--- a/assets/src/ba_data/python/ba/_plugin.py
+++ b/assets/src/ba_data/python/ba/_plugin.py
@ -117,9 +117,10 @@ class PluginSubsystem:
                     subs=[('${NUM}', str(len(disappeared_plugs)))]),
                color=(1, 1, 0),
            )
+            plugnames = ', '.join(disappeared_plugs)
            _ba.log(
                f'{len(disappeared_plugs)} plugin(s) no longer found:'
-                f' {str(disappeared_plugs)[1:-1]}.',
+                f' {plugnames}.',
                to_server=False)
            for goneplug in disappeared_plugs:
                del _ba.app.config['Plugins'][goneplug]
--- a/src/ballistica/app/app_globals.cc
+++ b/src/ballistica/app/app_globals.cc
@ -2,11 +2,17 @@

 #include "ballistica/app/app_globals.h"

+#include <cstring>
+
 namespace ballistica {

 AppGlobals::AppGlobals(int argc_in, char** argv_in)
-    : argc{argc_in},
-      argv{argv_in},
-      main_thread_id{std::this_thread::get_id()} {}
+    : argc{argc_in}, argv{argv_in}, main_thread_id{std::this_thread::get_id()} {
+  // Enable extra timing logs via env var.
+  const char* debug_timing_env = getenv("BA_DEBUG_TIMING");
+  if (debug_timing_env != nullptr && !strcmp(debug_timing_env, "1")) {
+    debug_timing = true;
+  }
+}

 }  // namespace ballistica
--- a/src/ballistica/app/app_globals.h
+++ b/src/ballistica/app/app_globals.h
@ -60,6 +60,7 @@ class AppGlobals {
  std::string user_agent_string{"BA_USER_AGENT_UNSET (" BA_PLATFORM_STRING ")"};
  int return_value{};
  bool is_stdin_a_terminal{true};
+  bool debug_timing{};
  std::thread::id main_thread_id{};
  bool is_bootstrapped{};
  bool args_handled{};
--- a/src/ballistica/ballistica.cc
+++ b/src/ballistica/ballistica.cc
@ -21,7 +21,7 @@
 namespace ballistica {

 // These are set automatically via script; don't modify them here.
-const int kAppBuildNumber = 20638;
+const int kAppBuildNumber = 20641;
 const char* kAppVersion = "1.7.4";

 // Our standalone globals.
--- a/src/ballistica/game/game.cc
+++ b/src/ballistica/game/game.cc
@ -650,7 +650,8 @@ void Game::Update() {
  in_update_ = false;

  // Report excessively long updates.
-  if (real_time >= next_long_update_report_time_) {
+  if (g_app_globals->debug_timing
+      && real_time >= next_long_update_report_time_) {
    auto duration{Platform::GetCurrentMilliseconds() - startms};

    // Complain when our full update takes longer than 1/60th second.
--- a/src/ballistica/python/python.cc
+++ b/src/ballistica/python/python.cc
@ -2246,15 +2246,20 @@ void Python::LogContextAuto() {
 }

 void Python::AcquireGIL() {
-  auto startms{Platform::GetCurrentMilliseconds()};
+  auto debug_timing{g_app_globals->debug_timing};
+  millisecs_t startms{debug_timing ? Platform::GetCurrentMilliseconds() : 0};
+
  if (thread_state_) {
    PyEval_RestoreThread(thread_state_);
    thread_state_ = nullptr;
  }
-  auto duration{Platform::GetCurrentMilliseconds() - startms};
-  if (duration > (1000 / 120)) {
-    Log("GIL acquire took too long (" + std::to_string(duration) + " ms).",
-        true, false);
+
+  if (debug_timing) {
+    auto duration{Platform::GetCurrentMilliseconds() - startms};
+    if (duration > (1000 / 120)) {
+      Log("GIL acquire took too long (" + std::to_string(duration) + " ms).",
+          true, false);
+    }
  }
 }
 void Python::ReleaseGIL() {