Record how long each fetcher took

go.mod

@@ -16,7 +16,7 @@ require (
 	github.com/pquerna/otp v1.4.0
 	github.com/rs/zerolog v1.29.0
 	github.com/tkw1536/goprogram v0.3.5
-	github.com/tkw1536/pkglib v0.0.0-20230428081457-cc953b972cee
+	github.com/tkw1536/pkglib v0.0.0-20230430134020-5cea3bd2ebdc
 	github.com/yuin/goldmark v1.5.4
 	github.com/yuin/goldmark-meta v1.1.0
 	golang.org/x/crypto v0.8.0

go.sum

@@ -115,10 +115,8 @@ github.com/tdewolff/parse v2.3.4+incompatible/go.mod h1:8oBwCsVmUkgHO8M5iCzSIDtp
 github.com/tdewolff/test v1.0.7 h1:8Vs0142DmPFW/bQeHRP3MV19m1gvndjUb1sn8yy74LM=
 github.com/tkw1536/goprogram v0.3.5 h1:S0axKo3R/vGa4zhYqYDKAZEPhAfwUSSeMtVwnAu4sNY=
 github.com/tkw1536/goprogram v0.3.5/go.mod h1:pYr4dMHOSVurbPQ4KTR0ett8XWNISbsRS6zlh9Nsxa8=
-github.com/tkw1536/pkglib v0.0.0-20230427125619-a4a18a5b7d15 h1:sVy3pSreMY5obUOGz2jCaPYbXh+5vklqMJrZZsrII+0=
+github.com/tkw1536/pkglib v0.0.0-20230430134020-5cea3bd2ebdc h1:uwS8zzIsiKU0H+irlZTd5AMOaGBSCaHsmi+6iVEXZjg=
-github.com/tkw1536/pkglib v0.0.0-20230427125619-a4a18a5b7d15/go.mod h1:0A1B9Cc5+yJXR3eeB14CqD4dFSbEjjWRo5Pr9M3XYuI=
+github.com/tkw1536/pkglib v0.0.0-20230430134020-5cea3bd2ebdc/go.mod h1:0A1B9Cc5+yJXR3eeB14CqD4dFSbEjjWRo5Pr9M3XYuI=
-github.com/tkw1536/pkglib v0.0.0-20230428081457-cc953b972cee h1:UmnHJnYpOon95zBUzzGteSkTAO6VSHacSbjFEKjEqo0=
-github.com/tkw1536/pkglib v0.0.0-20230428081457-cc953b972cee/go.mod h1:0A1B9Cc5+yJXR3eeB14CqD4dFSbEjjWRo5Pr9M3XYuI=
 github.com/xeipuuv/gojsonpointer v0.0.0-20180127040702-4e3ac2762d5f/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU=
 github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb h1:zGWFAtiMcyryUHoUjUJX0/lt1H2+i2Ka2n+D3DImSNo=
 github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU=

internal/wisski/ingredient/info/info.go

@@ -2,12 +2,16 @@ package info
 
 import (
 	"context"
+	"sync/atomic"
 	"time"
 
+	"github.com/FAU-CDI/wisski-distillery/internal/phpx"
 	"github.com/FAU-CDI/wisski-distillery/internal/status"
 	"github.com/FAU-CDI/wisski-distillery/internal/wisski/ingredient"
 	"github.com/FAU-CDI/wisski-distillery/internal/wisski/ingredient/php"
+	"github.com/rs/zerolog"
 	"github.com/tkw1536/pkglib/lifetime"
+	"github.com/tkw1536/pkglib/sema"
 	"golang.org/x/sync/errgroup"
 )
 
@@ -34,24 +38,72 @@ func (wisski *Info) Information(ctx context.Context, quick bool) (info status.Wi
 		Context: ctx,
 	}
 
-	// potentially setup a new server
+	var serversUsed uint64
-	if !flags.Quick {
+	pool := sema.Pool[*phpx.Server]{
-		flags.Server = wisski.Dependencies.PHP.NewServer()
+		// limit the number of processes running in this container
-		if err == nil {
+		// to avoid long overheads
-			defer flags.Server.Close()
+		Limit: 5,
+		New: func() *phpx.Server {
+			atomic.AddUint64(&serversUsed, 1)
+			return wisski.Dependencies.PHP.NewServer()
+		},
+		Discard: func(s *phpx.Server) {
+			s.Close()
+		},
+	}
+	defer pool.Close()
+
+	// setup a dictionary to record data about how long each operation took.
+	// we use a slice as opposed to a map to avoid having to mutex!
+	fetcherTimes := make([]time.Duration, len(wisski.Dependencies.Fetchers))
+	recordTime := func(i int) func() {
+		start := time.Now()
+		return func() {
+			fetcherTimes[i] = time.Since(start)
 		}
 	}
 
-	// run all the fetchers!
+	start := time.Now()
-	var group errgroup.Group
+	{
-	for _, fetcher := range wisski.Dependencies.Fetchers {
+		var group errgroup.Group
-		fetcher := fetcher
+		for i, fetcher := range wisski.Dependencies.Fetchers {
-		group.Go(func() error {
+			fetcher, flags, i := fetcher, flags, i
-			return fetcher.Fetch(flags, &info)
+			group.Go(func() error {
-		})
+				// quick: don't need to create servers
+				if flags.Quick {
+					defer recordTime(i)()
+					return fetcher.Fetch(flags, &info)
+				}
+
+				// complete: need to use a server from the pool
+				return pool.Use(func(s *phpx.Server) error {
+					defer recordTime(i)()
+					flags.Server = s
+					return fetcher.Fetch(flags, &info)
+				})
+			})
+		}
+
+		// wait for all the results
+		err = group.Wait()
+	}
+	took := time.Since(start)
+
+	var tookSum time.Duration
+
+	// get a map of how long each fetcher took
+	times := zerolog.Dict()
+	for i, fetcher := range wisski.Dependencies.Fetchers {
+		tookSum += fetcherTimes[i]
+		times = times.Dur(fetcher.Name(), fetcherTimes[i])
 	}
 
-	err = group.Wait()
+	// compute the ratio taken
+	tookRatio := float64(took) / float64(tookSum)
+
+	// and send it to debugging output
+	zerolog.Ctx(ctx).Debug().Uint64("servers", serversUsed).Dict("fetchers_took_ms", times).Dur("took_ms", took).Dur("took_sum_ms", tookSum).Float64("took_ratio", tookRatio).Bool("quick", quick).Msg("ran information fetchers")
+
 	return
 }