feat: Add buffering to provisioner job logs (#4918)

* feat: Add bufferring to provisioner job logs This should improve overall build performance, and especially under load. It removes the old `id` column on the `provisioner_job_logs` table and replaces it with an auto-incrementing big integer to preserve order. Funny enough, we never had to care about order before because inserts would at minimum be 1ms different. Now they aren't, so the order needs to be preserved. * Fix log bufferring * Fix frontend log streaming * Fix JS test
coder · Nov 7, 2022 · 3028185 · 3028185
1 parent 531f7cd
commit 3028185
Show file tree

Hide file tree

Showing 34 changed files with 300 additions and 476 deletions.
diff --git a/cli/cliui/provisionerjob.go b/cli/cliui/provisionerjob.go
@@ -16,14 +16,14 @@ import (
 	"github.com/coder/coder/codersdk"
 )
 
-func WorkspaceBuild(ctx context.Context, writer io.Writer, client *codersdk.Client, build uuid.UUID, before time.Time) error {
+func WorkspaceBuild(ctx context.Context, writer io.Writer, client *codersdk.Client, build uuid.UUID) error {
 	return ProvisionerJob(ctx, writer, ProvisionerJobOptions{
 		Fetch: func() (codersdk.ProvisionerJob, error) {
 			build, err := client.WorkspaceBuild(ctx, build)
 			return build.Job, err
 		},
 		Logs: func() (<-chan codersdk.ProvisionerJobLog, io.Closer, error) {
-			return client.WorkspaceBuildLogsAfter(ctx, build, before)
+			return client.WorkspaceBuildLogsAfter(ctx, build, 0)
 		},
 	})
 }

diff --git a/cli/create.go b/cli/create.go
@@ -139,7 +139,6 @@ func create() *cobra.Command {
 				return err
 			}
 
-			after := time.Now()
 			workspace, err := client.CreateWorkspace(cmd.Context(), organization.ID, codersdk.Me, codersdk.CreateWorkspaceRequest{
 				TemplateID:        template.ID,
 				Name:              workspaceName,
@@ -151,7 +150,7 @@ func create() *cobra.Command {
 				return err
 			}
 
-			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, workspace.LatestBuild.ID, after)
+			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, workspace.LatestBuild.ID)
 			if err != nil {
 				return err
 			}
@@ -238,7 +237,6 @@ PromptParamLoop:
 	_, _ = fmt.Fprintln(cmd.OutOrStdout())
 
 	// Run a dry-run with the given parameters to check correctness
-	after := time.Now()
 	dryRun, err := client.CreateTemplateVersionDryRun(cmd.Context(), templateVersion.ID, codersdk.CreateTemplateVersionDryRunRequest{
 		WorkspaceName:   args.NewWorkspaceName,
 		ParameterValues: parameters,
@@ -255,7 +253,7 @@ PromptParamLoop:
 			return client.CancelTemplateVersionDryRun(cmd.Context(), templateVersion.ID, dryRun.ID)
 		},
 		Logs: func() (<-chan codersdk.ProvisionerJobLog, io.Closer, error) {
-			return client.TemplateVersionDryRunLogsAfter(cmd.Context(), templateVersion.ID, dryRun.ID, after)
+			return client.TemplateVersionDryRunLogsAfter(cmd.Context(), templateVersion.ID, dryRun.ID, 0)
 		},
 		// Don't show log output for the dry-run unless there's an error.
 		Silent: true,

diff --git a/cli/delete.go b/cli/delete.go
@@ -47,7 +47,6 @@ func deleteWorkspace() *cobra.Command {
 				)
 			}
 
-			before := time.Now()
 			build, err := client.CreateWorkspaceBuild(cmd.Context(), workspace.ID, codersdk.CreateWorkspaceBuildRequest{
 				Transition:       codersdk.WorkspaceTransitionDelete,
 				ProvisionerState: state,
@@ -57,7 +56,7 @@ func deleteWorkspace() *cobra.Command {
 				return err
 			}
 
-			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, build.ID, before)
+			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, build.ID)
 			if err != nil {
 				return err
 			}

diff --git a/cli/portforward.go b/cli/portforward.go
@@ -79,7 +79,7 @@ func portForward() *cobra.Command {
 				return xerrors.New("workspace must be in start transition to port-forward")
 			}
 			if workspace.LatestBuild.Job.CompletedAt == nil {
-				err = cliui.WorkspaceBuild(ctx, cmd.ErrOrStderr(), client, workspace.LatestBuild.ID, workspace.CreatedAt)
+				err = cliui.WorkspaceBuild(ctx, cmd.ErrOrStderr(), client, workspace.LatestBuild.ID)
 				if err != nil {
 					return err
 				}

diff --git a/cli/ssh.go b/cli/ssh.go
@@ -250,7 +250,7 @@ func getWorkspaceAndAgent(ctx context.Context, cmd *cobra.Command, client *coder
 		return codersdk.Workspace{}, codersdk.WorkspaceAgent{}, xerrors.New("workspace must be in start transition to ssh")
 	}
 	if workspace.LatestBuild.Job.CompletedAt == nil {
-		err := cliui.WorkspaceBuild(ctx, cmd.ErrOrStderr(), client, workspace.LatestBuild.ID, workspace.CreatedAt)
+		err := cliui.WorkspaceBuild(ctx, cmd.ErrOrStderr(), client, workspace.LatestBuild.ID)
 		if err != nil {
 			return codersdk.Workspace{}, codersdk.WorkspaceAgent{}, err
 		}

diff --git a/cli/start.go b/cli/start.go
@@ -25,15 +25,14 @@ func start() *cobra.Command {
 			if err != nil {
 				return err
 			}
-			before := time.Now()
 			build, err := client.CreateWorkspaceBuild(cmd.Context(), workspace.ID, codersdk.CreateWorkspaceBuildRequest{
 				Transition: codersdk.WorkspaceTransitionStart,
 			})
 			if err != nil {
 				return err
 			}
 
-			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, build.ID, before)
+			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, build.ID)
 			if err != nil {
 				return err
 			}

diff --git a/cli/state.go b/cli/state.go
@@ -5,7 +5,6 @@ import (
 	"io"
 	"os"
 	"strconv"
-	"time"
 
 	"github.com/spf13/cobra"
 
@@ -100,7 +99,6 @@ func statePush() *cobra.Command {
 				return err
 			}
 
-			before := time.Now()
 			build, err = client.CreateWorkspaceBuild(cmd.Context(), workspace.ID, codersdk.CreateWorkspaceBuildRequest{
 				TemplateVersionID: build.TemplateVersionID,
 				Transition:        build.Transition,
@@ -109,7 +107,7 @@ func statePush() *cobra.Command {
 			if err != nil {
 				return err
 			}
-			return cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStderr(), client, build.ID, before)
+			return cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStderr(), client, build.ID)
 		},
 	}
 	cmd.Flags().IntVarP(&buildNumber, "build", "b", 0, "Specify a workspace build to target by name.")

diff --git a/cli/stop.go b/cli/stop.go
@@ -33,15 +33,14 @@ func stop() *cobra.Command {
 			if err != nil {
 				return err
 			}
-			before := time.Now()
 			build, err := client.CreateWorkspaceBuild(cmd.Context(), workspace.ID, codersdk.CreateWorkspaceBuildRequest{
 				Transition: codersdk.WorkspaceTransitionStop,
 			})
 			if err != nil {
 				return err
 			}
 
-			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, build.ID, before)
+			err = cliui.WorkspaceBuild(cmd.Context(), cmd.OutOrStdout(), client, build.ID)
 			if err != nil {
 				return err
 			}

diff --git a/cli/templatecreate.go b/cli/templatecreate.go
@@ -160,7 +160,6 @@ type createValidTemplateVersionArgs struct {
 }
 
 func createValidTemplateVersion(cmd *cobra.Command, args createValidTemplateVersionArgs, parameters ...codersdk.CreateParameterRequest) (*codersdk.TemplateVersion, []codersdk.CreateParameterRequest, error) {
-	before := time.Now()
 	client := args.Client
 
 	req := codersdk.CreateTemplateVersionRequest{
@@ -187,7 +186,7 @@ func createValidTemplateVersion(cmd *cobra.Command, args createValidTemplateVers
 			return client.CancelTemplateVersion(cmd.Context(), version.ID)
 		},
 		Logs: func() (<-chan codersdk.ProvisionerJobLog, io.Closer, error) {
-			return client.TemplateVersionLogsAfter(cmd.Context(), version.ID, before)
+			return client.TemplateVersionLogsAfter(cmd.Context(), version.ID, 0)
 		},
 	})
 	if err != nil {

diff --git a/cli/update.go b/cli/update.go
@@ -2,7 +2,6 @@ package cli
 
 import (
 	"fmt"
-	"time"
 
 	"github.com/spf13/cobra"
 
@@ -57,7 +56,6 @@ func update() *cobra.Command {
 				return nil
 			}
 
-			before := time.Now()
 			build, err := client.CreateWorkspaceBuild(cmd.Context(), workspace.ID, codersdk.CreateWorkspaceBuildRequest{
 				TemplateVersionID: template.ActiveVersionID,
 				Transition:        workspace.LatestBuild.Transition,
@@ -66,7 +64,7 @@ func update() *cobra.Command {
 			if err != nil {
 				return err
 			}
-			logs, closer, err := client.WorkspaceBuildLogsAfter(cmd.Context(), build.ID, before)
+			logs, closer, err := client.WorkspaceBuildLogsAfter(cmd.Context(), build.ID, 0)
 			if err != nil {
 				return err
 			}

diff --git a/coderd/database/databasefake/databasefake.go b/coderd/database/databasefake/databasefake.go
@@ -2052,17 +2052,14 @@ func (q *fakeQuerier) GetProvisionerLogsByIDBetween(_ context.Context, arg datab
 		if jobLog.JobID != arg.JobID {
 			continue
 		}
-		if !arg.CreatedBefore.IsZero() && jobLog.CreatedAt.After(arg.CreatedBefore) {
+		if arg.CreatedBefore != 0 && jobLog.ID > arg.CreatedBefore {
 			continue
 		}
-		if !arg.CreatedAfter.IsZero() && jobLog.CreatedAt.Before(arg.CreatedAfter) {
+		if arg.CreatedAfter != 0 && jobLog.ID < arg.CreatedAfter {
 			continue
 		}
 		logs = append(logs, jobLog)
 	}
-	if len(logs) == 0 {
-		return nil, sql.ErrNoRows
-	}
 	return logs, nil
 }
 
@@ -2212,10 +2209,15 @@ func (q *fakeQuerier) InsertProvisionerJobLogs(_ context.Context, arg database.I
 	defer q.mutex.Unlock()
 
 	logs := make([]database.ProvisionerJobLog, 0)
+	id := int64(1)
+	if len(q.provisionerJobLogs) > 0 {
+		id = q.provisionerJobLogs[len(q.provisionerJobLogs)-1].ID
+	}
 	for index, output := range arg.Output {
+		id++
 		logs = append(logs, database.ProvisionerJobLog{
+			ID:        id,
 			JobID:     arg.JobID,
-			ID:        arg.ID[index],
 			CreatedAt: arg.CreatedAt[index],
 			Source:    arg.Source[index],
 			Level:     arg.Level[index],

diff --git a/coderd/database/dump.sql b/coderd/database/dump.sql
diff --git a/coderd/database/migrations/000071_provisioner_log_lines.down.sql b/coderd/database/migrations/000071_provisioner_log_lines.down.sql
@@ -0,0 +1,3 @@
+ALTER TABLE provisioner_job_logs DROP COLUMN id;
+
+ALTER TABLE provisioner_job_logs ADD COLUMN id uuid NOT NULL DEFAULT gen_random_uuid();
diff --git a/coderd/database/migrations/000071_provisioner_log_lines.up.sql b/coderd/database/migrations/000071_provisioner_log_lines.up.sql
@@ -0,0 +1,3 @@
+ALTER TABLE provisioner_job_logs DROP COLUMN id;
+
+ALTER TABLE provisioner_job_logs ADD COLUMN id BIGSERIAL PRIMARY KEY; 
diff --git a/coderd/database/models.go b/coderd/database/models.go
diff --git a/coderd/database/queries.sql.go b/coderd/database/queries.sql.go
diff --git a/coderd/database/queries/provisionerjoblogs.sql b/coderd/database/queries/provisionerjoblogs.sql
@@ -6,17 +6,14 @@ FROM
 WHERE
 	job_id = @job_id
 	AND (
-		created_at >= @created_after
-		OR created_at <= @created_before
-	)
-ORDER BY
-	created_at DESC;
+		id > @created_after
+		OR id < @created_before
+	) ORDER BY id;
 
 -- name: InsertProvisionerJobLogs :many
 INSERT INTO
 	provisioner_job_logs
 SELECT
-	unnest(@id :: uuid [ ]) AS id,
 	@job_id :: uuid AS job_id,
 	unnest(@created_at :: timestamptz [ ]) AS created_at,
 	unnest(@source :: log_source [ ]) AS source,