Add XHS publishing stage timing logs

cmd/mark2note/main.go

@@ -18,6 +18,7 @@ import (
 	"github.com/walker1211/mark2note/internal/deck"
 	"github.com/walker1211/mark2note/internal/poster"
 	"github.com/walker1211/mark2note/internal/render"
+	"github.com/walker1211/mark2note/internal/timing"
 	"github.com/walker1211/mark2note/internal/xhs"
 	"gopkg.in/yaml.v3"
 )
@@ -1175,7 +1176,9 @@ func runPrepareXHS(renderOpts Options, renderResult app.Result, stdout io.Writer
 }
 
 func runAutoPublishXHS(renderOpts Options, renderResult app.Result, stdout io.Writer, stderr io.Writer) int {
+	buildDone := timing.Stage("cmd.runAutoPublishXHS.build_options", timing.Field("images", len(renderResult.ImagePaths)))
 	publishOpts, err := buildAutoPublishXHSOptions(renderOpts, renderResult)
+	buildDone(err)
 	if err != nil {
 		switch {
 		case errors.Is(err, app.ErrLoadConfig):
@@ -1191,7 +1194,9 @@ func runAutoPublishXHS(renderOpts Options, renderResult app.Result, stdout io.Wr
 		fmt.Fprintf(stderr, "auto publish xhs failed: write xhs publish metadata: %v\n", err)
 		return 1
 	}
+	publishDone := timing.Stage("cmd.runAutoPublishXHS.publish", timing.Field("images", len(publishOpts.ImagePaths)), timing.Field("mode", publishOpts.Mode))
 	result, err := publishXHS(publishOpts)
+	publishDone(err)
 	if err != nil {
 		printPublishXHSError(stderr, err)
 		return 1
@@ -1210,7 +1215,7 @@ func nonEmptyStrings(values []string) []string {
 	return result
 }
 
-func run(args []string, stdout io.Writer, stderr io.Writer) int {
+func run(args []string, stdout io.Writer, stderr io.Writer) (code int) {
 	if len(args) > 0 {
 		switch args[0] {
 		case "capture-html":
@@ -1236,6 +1241,15 @@ func run(args []string, stdout io.Writer, stderr io.Writer) int {
 		return 1
 	}
 
+	done := timing.Stage("cmd.run")
+	defer func() {
+		var err error
+		if code != 0 {
+			err = errors.New("exit_nonzero")
+		}
+		done(err)
+	}()
+
 	generate := generatePreview
 	if strings.TrimSpace(opts.FromDeckPath) != "" {
 		generate = generateFromDeck
@@ -1446,7 +1460,9 @@ func runPublishXHS(args []string, stdout io.Writer, stderr io.Writer) int {
 			fmt.Fprintf(stderr, "error parsing flags: --meta cannot be combined with manual publish fields: %s\n", strings.Join(cliOpts.MetaConflictFlags, ", "))
 			return 1
 		}
+		metaDone := timing.Stage("cmd.runPublishXHS.read_metadata")
 		opts, err := readXHSPublishMeta(cliOpts.MetaPath)
+		metaDone(err)
 		if err != nil {
 			fmt.Fprintf(stderr, "error reading xhs publish metadata: %v\n", err)
 			return 1
@@ -1460,7 +1476,9 @@ func runPublishXHS(args []string, stdout io.Writer, stderr io.Writer) int {
 			fmt.Fprintf(stderr, "error validating xhs publish metadata: %v\n", err)
 			return 1
 		}
+		publishDone := timing.Stage("cmd.runPublishXHS.publish_metadata", timing.Field("images", len(opts.ImagePaths)), timing.Field("mode", opts.Mode))
 		result, err := publishXHS(opts)
+		publishDone(err)
 		if err != nil {
 			printPublishXHSError(stderr, err)
 			return 1
@@ -1477,7 +1495,9 @@ func runPublishXHS(args []string, stdout io.Writer, stderr io.Writer) int {
 		fmt.Fprintf(stderr, "error parsing flags: %v\n", err)
 		return 1
 	}
+	publishDone := timing.Stage("cmd.runPublishXHS.publish", timing.Field("images", len(opts.ImagePaths)), timing.Field("mode", opts.Mode))
 	result, err := publishXHS(opts)
+	publishDone(err)
 	if err != nil {
 		printPublishXHSError(stderr, err)
 		return 1

internal/app/publish_service.go

@@ -8,6 +8,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/walker1211/mark2note/internal/timing"
 	"github.com/walker1211/mark2note/internal/xhs"
 )
 
@@ -63,15 +64,24 @@ var (
 	ErrPublishExecute        = errors.New("publish execute failed")
 )
 
-func (s PublishService) Publish(opts PublishOptions) (PublishResult, error) {
+func (s PublishService) Publish(opts PublishOptions) (result PublishResult, err error) {
+	done := timing.Stage("app.PublishService.Publish", timing.Field("images", len(opts.ImagePaths)), timing.Field("live", strings.TrimSpace(opts.LiveReportPath) != ""))
+	defer func() { done(err) }()
+
+	resolveDone := timing.Stage("app.PublishService.resolve_title_content")
 	title, err := s.resolveTextInput(opts.Title, opts.TitleFile, "title")
-	if err != nil {
-		return PublishResult{}, err
-	}
-	content, err := s.resolveOptionalTextInput(opts.Content, opts.ContentFile, "content")
-	if err != nil {
-		return PublishResult{}, err
+	if err == nil {
+		content, err := s.resolveOptionalTextInput(opts.Content, opts.ContentFile, "content")
+		if err == nil {
+			resolveDone(nil)
+			return s.publishResolved(opts, title, content)
+		}
 	}
+	resolveDone(err)
+	return PublishResult{}, err
+}
+
+func (s PublishService) publishResolved(opts PublishOptions, title string, content string) (PublishResult, error) {
 	mode, err := xhs.ValidateMode(opts.Mode)
 	if err != nil {
 		return PublishResult{}, fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err)
@@ -81,15 +91,22 @@ func (s PublishService) Publish(opts PublishOptions) (PublishResult, error) {
 	if err != nil {
 		return PublishResult{}, fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err)
 	}
+	buildDone := timing.Stage("app.PublishService.build_request")
 	request, err := buildPublishRequest(opts, title, content, mode, scheduleTime)
+	if err == nil {
+		err = request.Validate(now)
+		if err != nil {
+			err = fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err)
+		}
+	}
+	buildDone(err)
 	if err != nil {
 		return PublishResult{}, err
 	}
-	if err := request.Validate(now); err != nil {
-		return PublishResult{}, fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err)
-	}
 	runtime := PublishRuntimeOptions{ChromePath: strings.TrimSpace(opts.ChromePath), Headless: opts.Headless, ProfileDir: strings.TrimSpace(opts.ProfileDir), ChromeArgs: trimOptionalSlice(opts.ChromeArgs)}
+	publishDone := timing.Stage("app.PublishService.orchestrator_publish", timing.Field("media", request.MediaKind), timing.Field("mode", request.Mode))
 	result, err := s.effectiveNewOrchestrator()(runtime).Publish(request, runtime)
+	publishDone(err)
 	if err != nil {
 		return PublishResult{Request: request, Result: result}, fmt.Errorf("%w: %w", ErrPublishExecute, err)
 	}

internal/app/service.go

@@ -18,6 +18,7 @@ import (
 	"github.com/walker1211/mark2note/internal/deck"
 	"github.com/walker1211/mark2note/internal/poster"
 	"github.com/walker1211/mark2note/internal/render"
+	"github.com/walker1211/mark2note/internal/timing"
 )
 
 type AnimatedOptions struct {
@@ -131,8 +132,13 @@ var (
 	ErrRenderPreview      = errors.New("render preview failed")
 )
 
-func (s Service) GeneratePreview(opts Options) (Result, error) {
+func (s Service) GeneratePreview(opts Options) (result Result, err error) {
+	done := timing.Stage("app.GeneratePreview")
+	defer func() { done(err) }()
+
+	loadConfigDone := timing.Stage("app.GeneratePreview.load_config")
 	cfg, err := s.effectiveLoadConfig()(opts.ConfigPath)
+	loadConfigDone(err)
 	if err != nil {
 		return Result{}, fmt.Errorf("%w: %v", ErrLoadConfig, err)
 	}
@@ -146,7 +152,9 @@ func (s Service) GeneratePreview(opts Options) (Result, error) {
 		}
 	}
 
+	readMarkdownDone := timing.Stage("app.GeneratePreview.read_markdown")
 	markdownBytes, err := s.effectiveReadFile()(opts.InputPath)
+	readMarkdownDone(err)
 	if err != nil {
 		return Result{}, fmt.Errorf("%w: %v", ErrReadMarkdown, err)
 	}
@@ -158,30 +166,44 @@ func (s Service) GeneratePreview(opts Options) (Result, error) {
 	}
 	if !matched {
 		s.PromptExtra = opts.PromptExtra
+		buildDeckDone := timing.Stage("app.GeneratePreview.ai_build_deck_json")
 		rawJSON, err = s.effectiveBuildDeckJSON()(cfg, markdown)
+		buildDeckDone(err)
 		if err != nil {
 			return Result{}, fmt.Errorf("%w: %w", ErrBuildDeckJSON, err)
 		}
 	}
 
+	parseDeckDone := timing.Stage("app.GeneratePreview.parse_deck")
 	d, err := deck.FromJSONWithMaxPages(rawJSON, opts.OutDir, cfg.Deck.MaxPages)
+	parseDeckDone(err)
 	if err != nil {
 		return Result{}, fmt.Errorf("%w: %v", ErrParseDeck, err)
 	}
 	d = moveLeadingMarkdownImageToCover(d, markdown)
 	var posterWarnings []string
-	if d, posterWarnings, err = s.hydratePosters(opts, d, markdown); err != nil {
+	hydratePostersDone := timing.Stage("app.GeneratePreview.hydrate_posters")
+	d, posterWarnings, err = s.hydratePosters(opts, d, markdown)
+	hydratePostersDone(err)
+	if err != nil {
 		return Result{}, err
 	}
 	d = hydrateLocalImageAssets(d, filepath.Dir(opts.InputPath))
 
-	result, err := s.renderDeck(opts, cfg, d, sourceRenderMeta{})
+	renderDeckDone := timing.Stage("app.GeneratePreview.render_deck")
+	result, err = s.renderDeck(opts, cfg, d, sourceRenderMeta{})
+	renderDeckDone(err)
 	result.Warnings = append(posterWarnings, result.Warnings...)
 	return result, err
 }
 
-func (s Service) GenerateFromDeck(opts Options) (Result, error) {
+func (s Service) GenerateFromDeck(opts Options) (result Result, err error) {
+	done := timing.Stage("app.GenerateFromDeck")
+	defer func() { done(err) }()
+
+	loadConfigDone := timing.Stage("app.GenerateFromDeck.load_config")
 	cfg, err := s.effectiveLoadConfig()(opts.ConfigPath)
+	loadConfigDone(err)
 	if err != nil {
 		return Result{}, fmt.Errorf("%w: %v", ErrLoadConfig, err)
 	}
@@ -193,24 +215,35 @@ func (s Service) GenerateFromDeck(opts Options) (Result, error) {
 			opts.OutDir = abs
 		}
 	}
+	readDeckDone := timing.Stage("app.GenerateFromDeck.read_deck")
 	deckBytes, err := s.effectiveReadFile()(opts.FromDeckPath)
+	readDeckDone(err)
 	if err != nil {
 		return Result{}, fmt.Errorf("%w: %v", ErrReadDeck, err)
 	}
+	parseDeckDone := timing.Stage("app.GenerateFromDeck.parse_deck")
 	d, err := deck.FromJSONWithMaxPages(string(deckBytes), opts.OutDir, cfg.Deck.MaxPages)
+	parseDeckDone(err)
 	if err != nil {
 		return Result{}, fmt.Errorf("%w: %v", ErrParseDeck, err)
 	}
 	var posterWarnings []string
-	if d, posterWarnings, err = s.hydratePosters(opts, d, ""); err != nil {
+	hydratePostersDone := timing.Stage("app.GenerateFromDeck.hydrate_posters")
+	d, posterWarnings, err = s.hydratePosters(opts, d, "")
+	hydratePostersDone(err)
+	if err != nil {
 		return Result{}, err
 	}
 	d = hydrateLocalImageAssets(d, filepath.Dir(opts.FromDeckPath))
+	readMetaDone := timing.Stage("app.GenerateFromDeck.read_render_meta")
 	meta, err := s.readRenderMetaForDeck(opts.FromDeckPath)
+	readMetaDone(err)
 	if err != nil {
 		return Result{}, err
 	}
-	result, err := s.renderDeck(opts, cfg, d, sourceRenderMeta{FromDeck: true, Meta: meta})
+	renderDeckDone := timing.Stage("app.GenerateFromDeck.render_deck")
+	result, err = s.renderDeck(opts, cfg, d, sourceRenderMeta{FromDeck: true, Meta: meta})
+	renderDeckDone(err)
 	result.Warnings = append(posterWarnings, result.Warnings...)
 	return result, err
 }

internal/render/renderer.go

@@ -12,6 +12,7 @@ import (
 	"time"
 
 	"github.com/walker1211/mark2note/internal/deck"
+	"github.com/walker1211/mark2note/internal/timing"
 )
 
 const defaultChromePath = "/Applications/Google Chrome.app/Contents/MacOS/Google Chrome"
@@ -92,7 +93,10 @@ func (execRunner) Run(name string, args ...string) error {
 	return cmd.Run()
 }
 
-func (r Renderer) Render(d deck.Deck) (RenderResult, error) {
+func (r Renderer) Render(d deck.Deck) (result RenderResult, err error) {
+	done := timing.Stage("render.Render", timing.Field("pages", len(d.Pages)))
+	defer func() { done(err) }()
+
 	if len(d.Pages) == 0 {
 		return RenderResult{}, fmt.Errorf("deck must contain at least 1 page for render")
 	}
@@ -105,31 +109,44 @@ func (r Renderer) Render(d deck.Deck) (RenderResult, error) {
 	mode, animatedResult := r.normalizedAnimated()
 	liveMode, liveWarnings := normalizeLiveOptions(r.Live)
 	captureMode, captureWarnings := r.normalizedCaptureTiming(mode, liveMode.Enabled)
-	if err := r.renderHTMLPages(d, captureMode); err != nil {
+	renderHTMLDone := timing.Stage("render.Render.renderHTMLPages", timing.Field("pages", len(d.Pages)))
+	err = r.renderHTMLPages(d, captureMode)
+	renderHTMLDone(err)
+	if err != nil {
 		return RenderResult{}, err
 	}
-	if err := r.CapturePNGs(d.Pages, outDir); err != nil {
+	captureDone := timing.Stage("render.Render.CapturePNGs", timing.Field("pages", len(d.Pages)))
+	err = r.CapturePNGs(d.Pages, outDir)
+	captureDone(err)
+	if err != nil {
 		return RenderResult{}, err
 	}
 	imagePaths := generatedPNGPaths(d.Pages, outDir)
 	warnings := append([]string(nil), animatedResult.Warnings...)
 	warnings = append(warnings, liveWarnings...)
 	warnings = append(warnings, captureWarnings...)
 	if captureMode.Enabled && (mode.Enabled || liveMode.Enabled) {
-		warnings = append(warnings, r.runAnimatedExports(d.Pages, outDir, captureMode, mode, liveMode)...)
+		animatedDone := timing.Stage("render.Render.animated_live_exports", timing.Field("pages", len(d.Pages)), timing.Field("animated", mode.Enabled), timing.Field("live", liveMode.Enabled))
+		animatedWarnings := r.runAnimatedExports(d.Pages, outDir, captureMode, mode, liveMode)
+		animatedDone(nil)
+		warnings = append(warnings, animatedWarnings...)
 	}
-	result := RenderResult{Warnings: warnings, ImagePaths: imagePaths}
+	result = RenderResult{Warnings: warnings, ImagePaths: imagePaths}
 	if r.ImportPhotos {
+		importDone := timing.Stage("render.Render.import_photos", timing.Field("pages", len(d.Pages)))
 		delivery, err := r.deliverPNGImport(outDir, d.Pages)
+		importDone(err)
 		result.ImportReport = &delivery.Report
 		result.ImportReportPath = delivery.ReportPath
 		if err != nil {
 			return result, err
 		}
 	}
 	if liveMode.Enabled && liveMode.Assemble && liveMode.ImportPhotos {
+		liveImportDone := timing.Stage("render.Render.live_import_photos", timing.Field("pages", len(d.Pages)))
 		sourceDir, importDir, err := r.liveImportSourceDirs(outDir, d.Pages, liveMode)
 		if err != nil {
+			liveImportDone(err)
 			return result, err
 		}
 		delivery, err := r.liveDeliveryOrchestrator().Deliver(liveDeliveryRequest{
@@ -138,6 +155,7 @@ func (r Renderer) Render(d deck.Deck) (RenderResult, error) {
 			AlbumName:     liveMode.ImportAlbum,
 			ImportTimeout: liveMode.ImportTimeout,
 		})
+		liveImportDone(err)
 		result.DeliveryReport = &delivery.Report
 		result.DeliveryReportPath = delivery.ReportPath
 		if err != nil {
@@ -351,7 +369,10 @@ func (r Renderer) CaptureHTMLPath(inputPath string) error {
 	return r.runCaptureTasksWithJobs(tasks, r.effectiveJobs())
 }
 
-func (r Renderer) runAnimatedExports(pages []deck.Page, outDir string, captureMode normalizedAnimatedOptions, animated normalizedAnimatedOptions, live normalizedLiveOptions) []string {
+func (r Renderer) runAnimatedExports(pages []deck.Page, outDir string, captureMode normalizedAnimatedOptions, animated normalizedAnimatedOptions, live normalizedLiveOptions) (warnings []string) {
+	done := timing.Stage("render.runAnimatedExports", timing.Field("pages", len(pages)), timing.Field("animated", animated.Enabled), timing.Field("live", live.Enabled))
+	defer func() { done(nil) }()
+
 	tasks := buildAnimatedCaptureTasks(pages, outDir, captureMode)
 	warningsList := make([]string, 0, 3)
 	if len(tasks) == 0 {
@@ -452,14 +473,18 @@ func (r Renderer) runAnimatedExports(pages []deck.Page, outDir string, captureMo
 		// while frame capture within a single page stays serial (1) to preserve frame
 		// order. Concurrent makelive invocations have shown intermittent segfaults in
 		// practice, so assemble runs sequentially here in original page order.
+		assembleDone := timing.Stage("render.runAnimatedExports.live_assemble", timing.Field("pages", len(assembleTasks)))
+		var assembleErr error
 		for _, task := range assembleTasks {
 			if task == nil {
 				continue
 			}
 			if err := liveAssembler.Assemble(*task); err != nil {
+				assembleErr = err
 				collected = append(collected, fmt.Sprintf("live assemble failed for %s: %v", task.PageName, err))
 			}
 		}
+		assembleDone(assembleErr)
 	}
 	sort.Strings(collected)
 	return collected