chore(startup): measure the part of a slow launch the log could not see
An operator reporting "nothing happens for two or three seconds after I click" was impossible to answer from opslog.log, because the first line applog writes already sits inside startup(). Everything spent loading the binary and creating the WebView2 environment happened before the log begins. In one of the reported logs, startup() to window-visible is 251 ms end to end - so whatever the wait is, it is not OpsLog initialising. It just could not be proven, only asserted. processStart is stamped on the first instruction of main. Two lines now bracket the launch: how long was spent before startup() ran at all, and click-to-window, which is the only number that matches what the operator experiences.
This commit is contained in:
@@ -964,7 +964,12 @@ func (a *App) startup(ctx context.Context) {
|
||||
// impossible: the copy someone is actually running is not always the one they
|
||||
// think they installed, and the version shown in the UI is the only clue.
|
||||
exe, _ := os.Executable()
|
||||
applog.Printf("startup: OpsLog %s — %s", appVersion, exe)
|
||||
// Everything before this line is outside our control: Windows mapping a 30 MB
|
||||
// binary, an antivirus reading all of it, and Wails creating the WebView2
|
||||
// environment. Logging it separates "OpsLog is slow" from "starting OpsLog is
|
||||
// slow", which are two different problems with two different fixes.
|
||||
applog.Printf("startup: OpsLog %s — %s (%.0f ms before startup: exe load + WebView2)",
|
||||
appVersion, exe, float64(time.Since(processStart).Microseconds())/1000)
|
||||
applog.Printf("startup: data dir = %s", dataDir)
|
||||
// The local SQLite file ALWAYS holds per-operator configuration — settings,
|
||||
// station profiles, rigs/antennas, cluster nodes, UDP, QSL templates, award
|
||||
@@ -1405,6 +1410,10 @@ func (a *App) startup(ctx context.Context) {
|
||||
func (a *App) domReady(ctx context.Context) {
|
||||
a.restoreWindowPosition()
|
||||
wruntime.WindowShow(ctx)
|
||||
// The one number that matches what the operator actually experiences: click
|
||||
// to window. Anything else measures a part of it.
|
||||
applog.Printf("startup: window visible %.0f ms after launch",
|
||||
float64(time.Since(processStart).Microseconds())/1000)
|
||||
}
|
||||
|
||||
// StartupStatus returns a diagnostic snapshot for the frontend.
|
||||
|
||||
@@ -67,6 +67,17 @@ func acquireInstance(postUpdate bool) bool {
|
||||
return false
|
||||
}
|
||||
|
||||
// processStart is stamped on the very first instruction of main, before the
|
||||
// single-instance guard and before anything else runs.
|
||||
//
|
||||
// It exists to split a slow launch in two, because the log alone could not: the
|
||||
// first line applog writes already sits inside startup(), so everything spent
|
||||
// loading the binary and creating the WebView2 environment happened before the
|
||||
// log begins and was invisible. An operator reporting "nothing happens for three
|
||||
// seconds" was impossible to answer from a file whose first timestamp is the
|
||||
// moment the app was already running.
|
||||
var processStart = time.Now()
|
||||
|
||||
func main() {
|
||||
// Single-instance guard: if OpsLog is already running, focus that window and
|
||||
// exit instead of spawning a duplicate. A second process would open its own
|
||||
|
||||
Reference in New Issue
Block a user