feat(coderd/database/dbpurge): retain most recent agent build logs #14460

johnstcn · 2024-08-27T21:42:49Z

Builds upon #14480
Addresses #10576

Updates the DeleteOldWorkspaceAgentLogs to:

Retain logs for the most recent build regardless of age,
Delete logs for agents that never connected and were created before the cutoff for deleting logs while still retaining the logs most recent build.

The motivation for the second changes is from running the following query on the dogfood database:

coder=> SELECT COUNT(*), MIN(workspace_agents.created_at) FROM workspace_agent_logs 
JOIN workspace_agents 
ON workspace_agent_logs.agent_id = workspace_agents.id
WHERE workspace_agents.last_connected_at IS NULL
AND workspace_agents.created_at < (NOW() - INTERVAL '7 days');
 count |              min              
-------+-------------------------------
  2169 | 2023-11-21 21:48:26.339238+00
(1 row)

johnstcn · 2024-08-30T10:54:48Z

coderd/database/dbpurge/dbpurge_test.go


-		// After dbpurge completes, the ticker is reset. Trap this call.
-		trapReset := clk.Trap().TickerReset()
+func awaitDoTick(ctx context.Context, t *testing.T, clk *quartz.Mock) chan struct{} {


addresses #14480 (comment)

johnstcn · 2024-08-30T10:55:21Z

coderd/database/dbpurge/dbpurge_test.go

@@ -181,139 +173,216 @@ func containsWorkspaceAgentStat(stats []database.GetWorkspaceAgentStatsRow, need

 //nolint:paralleltest // It uses LockIDDBPurge.
 func TestDeleteOldWorkspaceAgentLogs(t *testing.T) {
-	db, _ := dbtestutil.NewDB(t)
+	ctx := testutil.Context(t, testutil.WaitShort)


Addresses #14480 (comment)

…t builds and delete never-connected workspaces

johnstcn · 2024-08-30T11:01:35Z

coderd/database/dbpurge/dbpurge.go

+	// Start the ticker with the initial delay.
+	ticker := clk.NewTicker(delay)


Review: I found this to be the source of a race condition while testing.
I moved the initial 'tick' to instead be inside the goroutine below.

What was the race condition?

It may actually be the same race condition you mentioned below, just moved around slightly.

johnstcn · 2024-08-30T11:02:13Z

coderd/database/dbpurge/dbpurge_test.go

-	now := dbtime.Now()
-
-	//nolint:paralleltest // It uses LockIDDBPurge.
-	t.Run("AgentHasNotConnectedSinceWeek_LogsExpired", func(t *testing.T) {


Review: I collapsed both of the sub-tests into a single test with more breadth.

johnstcn · 2024-08-30T11:03:24Z

coderd/database/queries/workspaceagents.sql

 -- If an agent hasn't connected in the last 7 days, we purge it's logs.
+-- Exception: if the logs are related to the latest build, we keep those around.
 -- Logs can take up a lot of space, so it's important we clean up frequently.
 -- name: DeleteOldWorkspaceAgentLogs :exec
-DELETE FROM workspace_agent_logs WHERE agent_id IN
-	(SELECT id FROM workspace_agents WHERE last_connected_at IS NOT NULL
-		AND last_connected_at < @threshold :: timestamptz);
+WITH
+	latest_builds AS (
+		SELECT
+			workspace_id, max(build_number) AS max_build_number
+		FROM
+			workspace_builds
+		GROUP BY
+			workspace_id
+	),
+	old_agents AS (
+		SELECT
+			wa.id
+		FROM
+			workspace_agents AS wa
+		JOIN
+			workspace_resources AS wr
+		ON
+			wa.resource_id = wr.id
+		JOIN
+			workspace_builds AS wb
+		ON
+			wb.job_id = wr.job_id
+		LEFT JOIN
+			latest_builds
+		ON
+			latest_builds.workspace_id = wb.workspace_id
+		AND
+			latest_builds.max_build_number = wb.build_number
+		WHERE
+			-- Filter out the latest builds for each workspace.
+			latest_builds.workspace_id IS NULL
+		AND CASE
+			-- If the last time the agent connected was before @threshold
+			WHEN wa.last_connected_at IS NOT NULL THEN
+				 wa.last_connected_at < @threshold :: timestamptz
+			-- The agent never connected, and was created before @threshold
+			ELSE wa.created_at < @threshold :: timestamptz
+		END
+	)
+DELETE FROM workspace_agent_logs WHERE agent_id IN (SELECT id FROM old_agents);


This is the main change here. I welcome any further scrutiny or suggestions of this query.

I realize that old_agents can potentially get pretty big, but #14340 may help address this.

Would be interesting to see a https://explain.dalibo.com against dogfood. If the postgres query analyzer is working good with this query, it should hopefully be able to minimize the work in the CTE, but since it's a CTE it might fail at that optimization. Might actually produce a better result moving the old agents CTE inline in the delete.

I ran the query and two variants (one with the old_agents CTE inlined, and one with both CTEs inelined).

The plan looks basically the same for all three:

Original Query

old_agents CTE inlined

Both CTEs inlined

Thanks! Looks like there's not much difference and the original is easiest to plan for so might as well leave it. Perhaps issues may surface on a larger scale but I think it's alright to deal with those as they appear.

(Side note: So many sequential scans though, guess we don't have indexes to optimize this join order :/.)

mtojek

Correct me if I'm wrong, with this change you leave the latest workspace build logs as the agent might have not connected yet?

If I understood you weel, then 👍 from me.

johnstcn · 2024-08-30T14:33:28Z

Correct me if I'm wrong, with this change you leave the latest workspace build logs as the agent might have not connected yet?

Correct, that was the overall consensus from #10576

dannykopping · 2024-08-30T13:26:29Z

coderd/database/dbmem/dbmem.go

-		if !toBeDeleted {
-			validLogs = append(validLogs, log)
+	/*
+		old_agents AS (


This is really nice!

I'm concerned it'll go stale...
Although it could be argued all the business logic duplicated in this file is stale the second it's written.
We really need to get rid of dbmem.

dannykopping · 2024-08-30T14:37:36Z

coderd/database/dbpurge/dbpurge.go

@@ -72,13 +75,15 @@ func New(ctx context.Context, logger slog.Logger, db database.Store, clk quartz.
 	go func() {
 		defer close(closed)
 		defer ticker.Stop()
+		// Force an initial tick immediately.
+		ticker.Reset(time.Nanosecond)


Won't this set the ticker's new period to a nanosecond?

I believe this is the idiomatic way to tick immediately:

ticker := time.NewTicker(period) defer ticker.Stop() for ; true; <- ticker.C { ... }

Won't this set the ticker's new period to a nanosecond?

Yes, briefly until the second prong of the select is reached. Then the ticker is stopped and doTick() executes. At the end of doTick(), the ticker is reset with a longer delay.

The correction reset happens in doTick, so yes and no. This does however introduce a race where we may tick two times before instead of once on startup.

tick reset nano

tick

<-ticker.C

tick

ticker.Stop()

doTick()

<-ticker.C (immediately after because of 4)

The "immediate tick" idiom you mention may not play nicely with <-ctx.Done()

Ah yeah, that's very possible. I didn't think about it when I commented but original code is also not impervious to this race.

An alternative non-racy way is to kick it off with a different channel:

var tickerC <-chan time.Time initC := make(chan time.Time, 1) initC <- time.Time{} close(initC) tickerC = initC // ... case tick := tickerC: tickerC = ticker.C doTick(...)

(Or a separate case if that's preferable.)

An alternative is to just call doTick() immediately before the for-select loop.

Get out of here @johnstcn with your good and reasonable ideas!

I think the "initCh" approach definitely has merits, but not sure if it's necessary here as the context is still available in doTick. :)

mafredri

Except for the ticker init change which may produce two initial ticks, LGTM.

mafredri · 2024-08-30T15:09:18Z

coderd/database/dbpurge/dbpurge.go

+	// Start the ticker with the initial delay.
+	ticker := clk.NewTicker(delay)


What was the race condition?

mafredri · 2024-08-30T15:12:52Z

coderd/database/dbpurge/dbpurge.go

@@ -72,13 +75,15 @@ func New(ctx context.Context, logger slog.Logger, db database.Store, clk quartz.
 	go func() {
 		defer close(closed)
 		defer ticker.Stop()
+		// Force an initial tick immediately.
+		ticker.Reset(time.Nanosecond)


The correction reset happens in doTick, so yes and no. This does however introduce a race where we may tick two times before instead of once on startup.

tick reset nano

tick

<-ticker.C

tick

ticker.Stop()

doTick()

<-ticker.C (immediately after because of 4)

mafredri · 2024-08-30T15:15:42Z

coderd/database/dbpurge/dbpurge_test.go

-func mustCreateAgentWithLogs(ctx context.Context, t *testing.T, db database.Store, user database.User, org database.Organization, tmpl database.Template, tv database.TemplateVersion, agentLastConnectedAt time.Time, output string) uuid.UUID {
-	agent := mustCreateAgent(t, db, user, org, tmpl, tv)
+	return ch
+}


Nice 👍🏻

johnstcn self-assigned this Aug 27, 2024

johnstcn force-pushed the cj/retain-last-build-logs branch 4 times, most recently from 139174a to 34be657 Compare August 29, 2024 15:59

johnstcn changed the base branch from main to cj/dbpurge-quartz August 29, 2024 15:59

johnstcn mentioned this pull request Aug 29, 2024

chore(coderd/database/dbpurge): replace usage of time.* with quartz #14480

Merged

johnstcn changed the title ~~wip: feat(coderd/database/dbpurge): retain most recent agent build logs~~ feat(coderd/database/dbpurge): retain most recent agent build logs Aug 29, 2024

johnstcn force-pushed the cj/dbpurge-quartz branch from a7e0f15 to e826ae9 Compare August 30, 2024 09:37

johnstcn force-pushed the cj/retain-last-build-logs branch from 12df09c to 3321a28 Compare August 30, 2024 09:38

johnstcn commented Aug 30, 2024

View reviewed changes

Base automatically changed from cj/dbpurge-quartz to main August 30, 2024 10:55

johnstcn added 8 commits August 30, 2024 11:57

chore: improve coverage of dbpurge tests for DeleteOldWorkspaceAgentLogs

9451962

feat(dbpurge): update DeleteOldWorkspaceAgentLogs query to keep lates…

0c14a3e

…t builds and delete never-connected workspaces

remove unnecessary columns from CTE

0af051e

fix test

dd97358

implement dbmem

2017434

ensure that ticks from quartz are dbtimey

725eeb0

extract awaitDoTick() test helper

591dd91

address race condition in initial tick

0f8ab25

johnstcn force-pushed the cj/retain-last-build-logs branch from 31c3351 to 0f8ab25 Compare August 30, 2024 11:00

johnstcn commented Aug 30, 2024

View reviewed changes

johnstcn marked this pull request as ready for review August 30, 2024 11:05

johnstcn requested review from mafredri, dannykopping and mtojek August 30, 2024 11:05

mtojek approved these changes Aug 30, 2024

View reviewed changes

dannykopping reviewed Aug 30, 2024

View reviewed changes

mafredri approved these changes Aug 30, 2024

View reviewed changes

fix double-tick startup race

5c77b5e

johnstcn merged commit 0f8251b into main Aug 30, 2024
27 checks passed

johnstcn deleted the cj/retain-last-build-logs branch August 30, 2024 16:39

github-actions bot locked and limited conversation to collaborators Aug 30, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(coderd/database/dbpurge): retain most recent agent build logs #14460

feat(coderd/database/dbpurge): retain most recent agent build logs #14460

johnstcn commented Aug 27, 2024 •

edited

Loading

johnstcn Aug 30, 2024

johnstcn Aug 30, 2024

johnstcn Aug 30, 2024

mafredri Aug 30, 2024

johnstcn Aug 30, 2024

johnstcn Aug 30, 2024

johnstcn Aug 30, 2024 •

edited

Loading

mafredri Aug 30, 2024

johnstcn Aug 30, 2024

mafredri Aug 30, 2024

mtojek left a comment

johnstcn commented Aug 30, 2024

dannykopping Aug 30, 2024

dannykopping Aug 30, 2024

johnstcn Aug 30, 2024

mafredri Aug 30, 2024

johnstcn Aug 30, 2024

mafredri Aug 30, 2024 •

edited

Loading

johnstcn Aug 30, 2024

mafredri Aug 30, 2024

johnstcn Aug 30, 2024

mafredri left a comment

mafredri Aug 30, 2024

mafredri Aug 30, 2024

mafredri Aug 30, 2024

		// Start the ticker with the initial delay.
		ticker := clk.NewTicker(delay)

feat(coderd/database/dbpurge): retain most recent agent build logs #14460

feat(coderd/database/dbpurge): retain most recent agent build logs #14460

Conversation

johnstcn commented Aug 27, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

johnstcn Aug 30, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mtojek left a comment

Choose a reason for hiding this comment

johnstcn commented Aug 30, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mafredri Aug 30, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mafredri left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

johnstcn commented Aug 27, 2024 •

edited

Loading

johnstcn Aug 30, 2024 •

edited

Loading

mafredri Aug 30, 2024 •

edited

Loading