Log failure-notification timing and plan faster Windows toasts.

Append app-side delays to logs/notify-timing.log, add a PowerShell baseline
script (~773 ms), and track native WinRT toasts in ROADMAP.

Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
2026-08-05 23:15:44 +03:00
parent 0aab9d8db6
commit 1e3d14bef2
6 changed files with 210 additions and 3 deletions
+2
View File
@@ -9,6 +9,8 @@ All notable GoSentry changes are recorded in this file.
- **`ui.run`** — after `NewWindow`, register `AppMetadata.Icon` on Windows so - **`ui.run`** — after `NewWindow`, register `AppMetadata.Icon` on Windows so
Fyne toasts pick up artwork without calling `SetIcon`, which would override Fyne toasts pick up artwork without calling `SetIcon`, which would override
the PE multi-size window/taskbar icon. 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.** **Sample jobs include a disabled failure test for desktop notifications.**
+22
View File
@@ -5,6 +5,28 @@ Completed work is recorded in [CHANGELOG.md](CHANGELOG.md), not here.
## Open Items ## 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 **13 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 (695874 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 ### Dynamic tray icon toggle
Fyne exposes `SetSystemTrayIcon` and related APIs only at application startup. Fyne exposes `SetSystemTrayIcon` and related APIs only at application startup.
+39
View File
@@ -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)
+16
View File
@@ -13,6 +13,8 @@ import (
"fyne.io/fyne/v2/theme" "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 // 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 // durable model still lives in src/domain, so UI code does not define a second
// copy of the scheduler data. // copy of the scheduler data.
@@ -73,10 +75,24 @@ func newMainView(w fyne.Window, svc *app.Service) (fyne.CanvasObject, func(time.
if r.State == "Failed" && if r.State == "Failed" &&
(r.Trigger == "Manual" || r.Trigger == "Schedule") && (r.Trigger == "Manual" || r.Trigger == "Schedule") &&
svc.ShouldNotifyOnFailure() { svc.ShouldNotifyOnFailure() {
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{ fyne.CurrentApp().SendNotification(&fyne.Notification{
Title: "GoSentry: Job Failed", Title: "GoSentry: Job Failed",
Content: r.JobName + ": " + r.Detail, 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)
}
})
} }
} }
if isError { if isError {
+69
View File
@@ -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
}
+59
View File
@@ -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)
}
}