diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index 52a48ea..7b775be 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -9,6 +9,8 @@ All notable GoSentry changes are recorded in this file. - **`ui.run`** — after `NewWindow`, register `AppMetadata.Icon` on Windows so Fyne toasts pick up artwork without calling `SetIcon`, which would override the PE multi-size window/taskbar icon. +- **`ui.notify_timing`** — append app-side failure-notification timing to + `logs/notify-timing.log` for diagnosing toast delay (OS latency excluded). **Sample jobs include a disabled failure test for desktop notifications.** diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index 53f764e..658f1ef 100644 --- a/docs/ROADMAP.md +++ b/docs/ROADMAP.md @@ -5,6 +5,28 @@ Completed work is recorded in [CHANGELOG.md](CHANGELOG.md), not here. ## Open Items +### Faster Windows failure notifications + +Fyne `SendNotification` on Windows does not call WinRT directly. Each toast +writes a short script to `%TEMP%` and runs it through a **new PowerShell +process** (`app/app_windows.go`), which typically adds **1–3 seconds** of cold +start before the toast appears. GoSentry's own path from run completion through +`SendNotification` is much smaller and is logged separately. + +**Baseline (2026-08-05, `scripts/measure-windows-toast.ps1`, 3 runs on dev +machine):** average **773 ms** per toast (695–874 ms), dominated by PowerShell +cold start. Re-run the script when comparing after a native toast implementation. + +**App-side timing:** each failure notification appends one line to +`logs/notify-timing.log` (`ms_after_run`, `ms_fyne_do`, `ms_send`, +`ms_app_total`). These columns end when Fyne returns from `SendNotification`; OS +toast latency is not included. + +**Direction:** add `src/platform/notify/` with a native Windows toast (WinRT or +a maintained Go wrapper), used for failure notifications on Windows. Keep Fyne +`SendNotification` on Linux (DBus / xdg-desktop-portal) unless profiling shows it +needs the same treatment. + ### Dynamic tray icon toggle Fyne exposes `SetSystemTrayIcon` and related APIs only at application startup. diff --git a/scripts/measure-windows-toast.ps1 b/scripts/measure-windows-toast.ps1 new file mode 100644 index 0000000..487f26a --- /dev/null +++ b/scripts/measure-windows-toast.ps1 @@ -0,0 +1,39 @@ +# Measures the latency of Fyne's Windows toast path: write a short PowerShell +# script to %TEMP% and run it via PowerShell -ExecutionPolicy Bypass, the same +# approach fyne.io/fyne/v2/app uses in app_windows.go SendNotification. +param( + [int]$Iterations = 3 +) + +$template = @' +$title = "GoSentry timing test" +$content = "benchmark" +$iconPath = "file:///" +[Windows.UI.Notifications.ToastNotificationManager, Windows.UI.Notifications, ContentType = WindowsRuntime] > $null +$template = [Windows.UI.Notifications.ToastNotificationManager]::GetTemplateContent([Windows.UI.Notifications.ToastTemplateType]::ToastImageAndText02) +$toastXml = [xml] $template.GetXml() +$toastXml.GetElementsByTagName("text")[0].AppendChild($toastXml.CreateTextNode($title)) > $null +$toastXml.GetElementsByTagName("text")[1].AppendChild($toastXml.CreateTextNode($content)) > $null +$toastXml.GetElementsByTagName("image")[0].SetAttribute("src", $iconPath) > $null +$xml = New-Object Windows.Data.Xml.Dom.XmlDocument +$xml.LoadXml($toastXml.OuterXml) +$toast = [Windows.UI.Notifications.ToastNotification]::new($xml) +[Windows.UI.Notifications.ToastNotificationManager]::CreateToastNotifier("ru.mixeme.gosentry.desktop").Show($toast); +'@ + +Write-Host "Fyne-style Windows toast latency ($Iterations run(s), no icon path):" +$totalMs = 0 +for ($i = 1; $i -le $Iterations; $i++) { + $scriptPath = Join-Path $env:TEMP ("fyne-timing-test-$i.ps1") + Set-Content -Path $scriptPath -Value $template -Encoding UTF8 + $sw = [System.Diagnostics.Stopwatch]::StartNew() + $launch = "(Get-Content -Encoding UTF8 -Path `"$scriptPath`" -Raw) | Invoke-Expression" + & PowerShell -ExecutionPolicy Bypass -Command $launch | Out-Null + $sw.Stop() + $ms = [int]$sw.ElapsedMilliseconds + $totalMs += $ms + Write-Host (" run {0}: {1} ms" -f $i, $ms) + Remove-Item $scriptPath -ErrorAction SilentlyContinue +} +$avg = [math]::Round($totalMs / [double]$Iterations) +Write-Host (" average: {0} ms" -f $avg) diff --git a/src/ui/mainwindow.go b/src/ui/mainwindow.go index fa7160a..ab1615c 100644 --- a/src/ui/mainwindow.go +++ b/src/ui/mainwindow.go @@ -13,6 +13,8 @@ import ( "fyne.io/fyne/v2/theme" ) +const runRecordTimeLayout = "2006-01-02 15:04:05" + // The UI package aliases domain types to keep widget callbacks short. The actual // durable model still lives in src/domain, so UI code does not define a second // copy of the scheduler data. @@ -73,9 +75,23 @@ func newMainView(w fyne.Window, svc *app.Service) (fyne.CanvasObject, func(time. if r.State == "Failed" && (r.Trigger == "Manual" || r.Trigger == "Schedule") && svc.ShouldNotifyOnFailure() { - fyne.CurrentApp().SendNotification(&fyne.Notification{ - Title: "GoSentry: Job Failed", - Content: r.JobName + ": " + r.Detail, + timing := notificationTiming{ + JobName: r.JobName, + EmittedAt: time.Now(), + } + if finished, err := time.ParseInLocation(runRecordTimeLayout, r.Time, time.Local); err == nil { + timing.RunFinished = finished + } + fyne.Do(func() { + timing.UIQueuedAt = time.Now() + fyne.CurrentApp().SendNotification(&fyne.Notification{ + Title: "GoSentry: Job Failed", + Content: r.JobName + ": " + r.Detail, + }) + timing.AfterSendAt = time.Now() + if err := appendNotificationTimingLog(svc.Store().Paths.LogsDir, timing); err != nil { + fyne.LogError("Failed to write notification timing log", err) + } }) } } diff --git a/src/ui/notify_timing.go b/src/ui/notify_timing.go new file mode 100644 index 0000000..f66f9cf --- /dev/null +++ b/src/ui/notify_timing.go @@ -0,0 +1,69 @@ +package ui + +import ( + "fmt" + "os" + "path/filepath" + "time" +) + +const notificationTimingLogName = "notify-timing.log" + +// notificationTiming captures wall-clock points from a failed run through +// SendNotification. It does not include OS toast display latency — Fyne on +// Windows shows toasts via a separate PowerShell process after SendNotification +// returns. +type notificationTiming struct { + JobName string + RunFinished time.Time + EmittedAt time.Time + UIQueuedAt time.Time + AfterSendAt time.Time +} + +func (t notificationTiming) formatLine() string { + return fmt.Sprintf( + "%s\tjob=%s\tms_after_run=%s\tms_fyne_do=%s\tms_send=%s\tms_app_total=%s\n", + t.AfterSendAt.Format(time.RFC3339Nano), + t.JobName, + msBetween(t.RunFinished, t.EmittedAt), + msBetween(t.EmittedAt, t.UIQueuedAt), + msBetween(t.UIQueuedAt, t.AfterSendAt), + msBetween(t.EmittedAt, t.AfterSendAt), + ) +} + +func msBetween(from, to time.Time) string { + if from.IsZero() || to.IsZero() || to.Before(from) { + return "-" + } + return fmt.Sprintf("%d", to.Sub(from).Milliseconds()) +} + +func appendNotificationTimingLog(logsDir string, timing notificationTiming) error { + if logsDir == "" { + return nil + } + if err := os.MkdirAll(logsDir, 0o755); err != nil { + return err + } + path := filepath.Join(logsDir, notificationTimingLogName) + file, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + if err != nil { + return err + } + defer file.Close() + + info, err := file.Stat() + if err != nil { + return err + } + if info.Size() == 0 { + if _, err := file.WriteString("# GoSentry failure-notification timing (app side only; OS toast delay is not included)\n" + + "# columns: timestamp job ms_after_run ms_fyne_do ms_send ms_app_total\n"); err != nil { + return err + } + } + _, err = file.WriteString(timing.formatLine()) + return err +} diff --git a/src/ui/notify_timing_test.go b/src/ui/notify_timing_test.go new file mode 100644 index 0000000..383ede5 --- /dev/null +++ b/src/ui/notify_timing_test.go @@ -0,0 +1,59 @@ +package ui + +import ( + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestNotificationTimingFormatLine(t *testing.T) { + runFinished := time.Date(2026, 8, 5, 23, 0, 0, 0, time.Local) + emitted := runFinished.Add(15 * time.Millisecond) + uiQueued := emitted.Add(4 * time.Millisecond) + afterSend := uiQueued.Add(2 * time.Millisecond) + + line := notificationTiming{ + JobName: "Failure notification test", + RunFinished: runFinished, + EmittedAt: emitted, + UIQueuedAt: uiQueued, + AfterSendAt: afterSend, + }.formatLine() + + if !strings.Contains(line, "job=Failure notification test") { + t.Fatalf("line = %q, want job name", line) + } + for _, want := range []string{"ms_after_run=15", "ms_fyne_do=4", "ms_send=2", "ms_app_total=6"} { + if !strings.Contains(line, want) { + t.Fatalf("line = %q, want substring %q", line, want) + } + } +} + +func TestAppendNotificationTimingLogWritesHeaderAndRow(t *testing.T) { + dir := t.TempDir() + timing := notificationTiming{ + JobName: "demo", + RunFinished: time.Now().Add(-10 * time.Millisecond), + EmittedAt: time.Now().Add(-5 * time.Millisecond), + UIQueuedAt: time.Now().Add(-2 * time.Millisecond), + AfterSendAt: time.Now(), + } + if err := appendNotificationTimingLog(dir, timing); err != nil { + t.Fatal(err) + } + + data, err := os.ReadFile(filepath.Join(dir, notificationTimingLogName)) + if err != nil { + t.Fatal(err) + } + text := string(data) + if !strings.HasPrefix(text, "# GoSentry failure-notification timing") { + t.Fatalf("log = %q, want header", text) + } + if !strings.Contains(text, "job=demo") { + t.Fatalf("log = %q, want timing row", text) + } +}