What version of Go are you using (go version)?

$ go version
go version go1.19 windows/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

$ go env
set GO111MODULE=on
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\ghall\AppData\Local\go-build
set GOENV=C:\Users\ghall\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\ghall\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\ghall\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.19
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\Users\ghall\Projects\garet\go.mod
set GOWORK=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=C:\Users\ghall\AppData\Local\Temp\go-build1322433840=/tmp/go-build -gno-record-gcc-switches

What did you do?

Interrupted a time.Sleep with function callbacks

The whole program:

//go:build js && wasm

package main

import (
	"log"
	"syscall/js"
	"time"
)

var animLoopJs js.Func

func animLoop(this js.Value, args []js.Value) any {
	log.Println("in anim loop")

	global := js.Global()
	global.Call("requestAnimationFrame", animLoopJs)
	return nil
}

func main() {
	animLoopJs = js.FuncOf(animLoop)

	global := js.Global()
	global.Call("requestAnimationFrame", animLoopJs)

	for {
		time.Sleep(50 * time.Millisecond)
		log.Println("in tick loop")
	}
}

What did you expect to see?

only calling one setTimeout every 50 ms

What did you see instead?

it seems that every time the program is interrupted while sleeping, it clears the timeouts and recreates them, leading to excessive amounts of setTimeout and clearTimeout calls

When logging scheduleTimeoutEvent and clearTimeoutEvent, the console is flooded with messages clearing the timeout only to recreate it moments later

On a separate, bigger, project

On another project, runtime.gopark takes up approximately 25% of execution time. Most of this is due to repeated calls of setTimeout and clearTimeout. It appears that the go runtime does a clearTimeout and setTimeout whenever it is awoken.

I implemented a patch that improves performance by keeping setTimeout tasks alive and counting the number of references to them:

// func scheduleTimeoutEvent(delay int64) int32
"runtime.scheduleTimeoutEvent": (sp) => {
	sp >>>= 0;
	const id = this._nextCallbackTimeoutID;
	this._nextCallbackTimeoutID++;

	const msec = new Date().getTime();
	const timeout = getInt64(sp + 8) + 1;
	const time = msec+timeout;

	this._timeoutIDs.set(id, time);

	const existing = this._scheduledTimeouts.get(time);
	if (existing != null) {
		existing.refs += 1;
	} else {
		this._scheduledTimeouts.set(time, {
			"task": setTimeout(
				() => {
					const existing = this._scheduledTimeouts.get(time);
					while (existing.refs > 0) {
						this._resume();
					}
				},
				timeout,
			),
			"refs": 1,
		});
	}
	this.mem.setInt32(sp + 16, id, true);
},

// func clearTimeoutEvent(id int32)
"runtime.clearTimeoutEvent": (sp) => {
	sp >>>= 0;
	const id = this.mem.getInt32(sp + 8, true);
	const time = this._timeoutIDs.get(id);
	this._timeoutIDs.delete(id);
	const existing = this._scheduledTimeouts.get(time);
	if (existing != null) {
		existing.refs -= 1;
	}
},

but this would ideally be fixed on the Go side

perf after above change: