diff --git a/pkg/model/initializers.go b/pkg/model/initializers.go index 7d9afca05..c42b7ef68 100644 --- a/pkg/model/initializers.go +++ b/pkg/model/initializers.go @@ -219,15 +219,29 @@ func parallelSlotsFromOptions(opts []string) string { func (ml *ModelLoader) backendLoader(opts ...Option) (client grpc.Backend, err error) { o := NewOptions(opts...) - xlog.Info("BackendLoader starting", "modelID", o.modelID, "backend", o.backendString, "model", o.model) + // backendLoader is not a synonym for "a model is being loaded": in + // distributed mode Load() deliberately bypasses the local cache and calls + // it on every inference request so SmartRouter re-picks a replica per + // request. Announcing a load unconditionally therefore made ordinary + // traffic against a resident model look like a retry storm in the INFO + // log. Reserve INFO for a genuine cold load; keep the per-call trace at + // DEBUG for anyone actually following the routing path. + coldLoad := !ml.isResident(o.modelID) + + if coldLoad { + xlog.Info("BackendLoader starting", "modelID", o.modelID, "backend", o.backendString, "model", o.model) + } else { + xlog.Debug("BackendLoader invoked for an already-resident model", "modelID", o.modelID, "backend", o.backendString, "model", o.model) + } // Surface the effective performance-relevant runtime options at load (some of // these are auto-tuned for the detected hardware). Logged once per load so an // admin can see what will actually run and pin or override any value in the // model YAML — or set LOCALAI_DISABLE_HARDWARE_DEFAULTS=true to turn the // hardware auto-tuning off entirely. Gated on an LLM-ish load (context set) so - // TTS/audio/other backends stay quiet. - if opt := o.gRPCOptions; opt != nil && opt.ContextSize > 0 { + // TTS/audio/other backends stay quiet, and on a cold load so it stays "once + // per load" rather than once per request. + if opt := o.gRPCOptions; coldLoad && opt != nil && opt.ContextSize > 0 { xlog.Info("effective runtime tuning (override in the model YAML; LOCALAI_DISABLE_HARDWARE_DEFAULTS=true disables hardware auto-tuning)", "modelID", o.modelID, "context", opt.ContextSize, diff --git a/pkg/model/initializers_load_logging_test.go b/pkg/model/initializers_load_logging_test.go new file mode 100644 index 000000000..e785b03db --- /dev/null +++ b/pkg/model/initializers_load_logging_test.go @@ -0,0 +1,102 @@ +package model + +import ( + "bytes" + "log/slog" + + pb "github.com/mudler/LocalAI/pkg/grpc/proto" + "github.com/mudler/LocalAI/pkg/system" + "github.com/mudler/xlog" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +// backendLoader is not a synonym for "a model is being loaded". In distributed +// mode Load() deliberately bypasses the local cache and calls backendLoader on +// every inference request so SmartRouter can re-pick a replica per request, so +// the function runs at request rate against an already-resident model. Emitting +// the load banner unconditionally made ordinary embedding traffic (~5 req/s) +// look like a retry storm in the INFO log and sent an engineer chasing a +// non-existent hot loop during an unrelated production investigation. INFO must +// mark a genuine cold load only; the per-call trace belongs at DEBUG. +var _ = Describe("backendLoader load logging", func() { + var ( + ml *ModelLoader + captured *bytes.Buffer + ) + + BeforeEach(func() { + systemState, err := system.GetSystemState(system.WithModelPath(GinkgoT().TempDir())) + Expect(err).ToNot(HaveOccurred()) + ml = NewModelLoader(systemState) + + // Capture at info level so a debug-level emission is filtered out: the + // assertions then fail on severity, not merely on wording. + captured = &bytes.Buffer{} + handler := slog.NewTextHandler(captured, &slog.HandlerOptions{Level: slog.LevelInfo}) + xlog.SetLogger(xlog.NewLoggerWithHandler(handler, xlog.LogLevelInfo)) + }) + + AfterEach(func() { + // xlog exposes no getter for the package logger, so restore the same + // default the suite entrypoint installs rather than the prior value. + xlog.SetLogger(xlog.NewLogger(xlog.LogLevel("info"), "text")) + }) + + Context("when the model is already resident", func() { + BeforeEach(func() { + resident := NewModel("resident-model", "127.0.0.1:65535", nil) + // Skip the gRPC health probe so the resident model survives the + // lookup without a live backend behind the address. + resident.MarkHealthy() + ml.mu.Lock() + ml.store.Set("resident-model", resident) + ml.mu.Unlock() + }) + + It("does not announce a load at info level", func() { + _, err := ml.backendLoader( + WithModelID("resident-model"), + WithModel("resident-model"), + WithBackendString("llama-cpp"), + WithLoadGRPCLoadModelOpts(&pb.ModelOptions{ContextSize: 4096}), + ) + Expect(err).ToNot(HaveOccurred()) + + Expect(captured.String()).ToNot(ContainSubstring("BackendLoader starting"), + "a request served by an already-resident model must not look like a cold load") + }) + + It("does not repeat the effective runtime tuning banner at info level", func() { + _, err := ml.backendLoader( + WithModelID("resident-model"), + WithModel("resident-model"), + WithBackendString("llama-cpp"), + WithLoadGRPCLoadModelOpts(&pb.ModelOptions{ContextSize: 4096}), + ) + Expect(err).ToNot(HaveOccurred()) + + Expect(captured.String()).ToNot(ContainSubstring("effective runtime tuning"), + "the tuning banner documents what a load will run with, so it belongs to a load") + }) + }) + + Context("when the model is not resident", func() { + It("still announces the cold load at info level", func() { + // The load itself fails (no such backend is installed); what is + // pinned here is that the banner is emitted before that, so + // suppressing the warm case does not silence real loads. + _, err := ml.backendLoader( + WithModelID("cold-model"), + WithModel("cold-model"), + WithBackendString("definitely-not-an-installed-backend"), + WithLoadGRPCLoadModelOpts(&pb.ModelOptions{ContextSize: 4096}), + ) + Expect(err).To(HaveOccurred()) + + Expect(captured.String()).To(ContainSubstring("BackendLoader starting")) + Expect(captured.String()).To(ContainSubstring("effective runtime tuning")) + }) + }) +}) diff --git a/pkg/model/loader.go b/pkg/model/loader.go index 827ce1bdd..6e0abee69 100644 --- a/pkg/model/loader.go +++ b/pkg/model/loader.go @@ -601,6 +601,20 @@ func (ml *ModelLoader) shutdownModel(ctx context.Context, modelName string, forc return ml.deleteProcess(ctx, modelName, force) } +// isResident reports whether the model store already holds an entry for +// modelID. Unlike checkIsLoaded it never probes the backend and never evicts, +// so it is safe to call on a per-request hot path: it answers "have we been +// here before?", which is exactly what the load logging needs to distinguish a +// cold load from routine traffic against a resident model. +func (ml *ModelLoader) isResident(modelID string) bool { + ml.mu.Lock() + store := ml.store + ml.mu.Unlock() + + _, ok := store.Get(modelID) + return ok +} + func (ml *ModelLoader) CheckIsLoaded(s string) *Model { release := ml.operations.acquire(s, false) defer release()