diff --git a/dUgcServer/Processing/UgcJobs.cpp b/dUgcServer/Processing/UgcJobs.cpp index 42e04eb1f..0f07a0f1f 100644 --- a/dUgcServer/Processing/UgcJobs.cpp +++ b/dUgcServer/Processing/UgcJobs.cpp @@ -1,5 +1,6 @@ #include "UgcJobs.h" +#include #include #include #include @@ -156,6 +157,18 @@ namespace UgcJobs { return true; } + std::optional WithIconTime(const std::string& stats, double iconMs, double& change) { + auto parsed = nlohmann::json::parse(stats, nullptr, false); + if (!parsed.is_object()) return std::nullopt; + auto& ms = parsed["ms"]; + if (!ms.is_object()) ms = nlohmann::json::object(); + const double before = ms.value("icon", 0.0); + change = iconMs - before; + ms["icon"] = std::lround(iconMs); + ms["total"] = std::max(0L, std::lround(ms.value("total", 0.0) + change)); + return parsed.dump(); + } + Outcome ProcessModel(const std::string& blob, UgcBricks::BrickLibrary& library, const Settings& settings, uint64_t seed, const UgcIconParams::Values& iconValues) { Outcome outcome; const auto started = std::chrono::steady_clock::now(); diff --git a/dUgcServer/Processing/UgcJobs.h b/dUgcServer/Processing/UgcJobs.h index d33c9ea31..f3c66ab9d 100644 --- a/dUgcServer/Processing/UgcJobs.h +++ b/dUgcServer/Processing/UgcJobs.h @@ -92,6 +92,13 @@ namespace UgcJobs { bool IconFromNif(const std::string& nif, const UgcRender::IconOptions& options, UgcStorage::Files& files, std::string& error, const std::map& tagLooks = {}, const std::set& overlayTags = {}); + /** + * A model's stats.json after its icon was drawn again in `iconMs`: ms.icon becomes that and ms.total changes by the + * difference, so the make's time keeps its icon's. `change` is the difference (the icon's time before is 0 when it + * wasn't recorded). nullopt when the stats can't be read. + */ + std::optional WithIconTime(const std::string& stats, double iconMs, double& change); + // The name of a group of shapes (its NiLODNode and shapes): S01_Opaque_Model, S01_Alpha_Model, S88_Metal_Model, // S89_Brushed_Model, S46_Glow_Model, S21_Glitter_Model and S21_GlitterAlpha_Model (transparent glitter; the ids from // the settings), at most 60 characters as LU Toolbox cuts them diff --git a/dUgcServer/Processing/UgcProcessor.cpp b/dUgcServer/Processing/UgcProcessor.cpp index b021574bb..437fa22fe 100644 --- a/dUgcServer/Processing/UgcProcessor.cpp +++ b/dUgcServer/Processing/UgcProcessor.cpp @@ -289,8 +289,13 @@ void UgcProcessor::Worker() { const auto nif = m_Storage.ReadNif(Kind::MODEL, job.id, "model.nif"); auto options = settings.icon; UgcIconParams::Apply(options, job.iconValues); + const auto iconStart = std::chrono::steady_clock::now(); done.outcome.ok = nif && UgcJobs::IconFromNif(*nif, options, done.outcome.files, done.outcome.error, settings.shaders.TagLooks(), settings.shaders.OverlayTags()); if (!nif) done.outcome.error = "no stored .nif"; + // The make's time keeps its icon's: the stats get the new icon's time, the row the difference (Collect) + const auto stats = done.outcome.ok ? m_Storage.ReadNif(Kind::MODEL, job.id, "stats.json") : std::nullopt; + const double iconMs = std::chrono::duration(std::chrono::steady_clock::now() - iconStart).count(); + if (const auto updated = stats ? UgcJobs::WithIconTime(*stats, iconMs, done.iconChangeMs) : std::nullopt) done.outcome.files["stats.json"] = *updated; } else { done.outcome = job.kind == Kind::MODEL ? UgcJobs::ProcessModel(job.blob, m_Library, settings, static_cast(job.id), job.iconValues) @@ -442,6 +447,15 @@ void UgcProcessor::Poll() { m_Wake.notify_all(); } +void UgcProcessor::RecordIconTime(LWOOBJID id, double changeMs) { + for (const auto& entry : Database::Get()->GetUgcEntries({ id })) { + if (entry.kind != IUgcLookup::eUgcKind::MODEL || entry.processMs == 0) continue; + // The icon is drawn on one thread, so its time is its CPU time too + const auto change = [changeMs](uint32_t value) { return static_cast(std::max(0.0, static_cast(value) + changeMs)); }; + Database::Get()->SetUgcModelProcessStats(id, { change(entry.processMs), change(entry.processCpuMs), entry.processMemoryKb }); + } +} + void UgcProcessor::Record(const Done& done) { // What the make cost (wall time, the worker's CPU time, the estimated memory), for the dashboard const IUgc::ProcessStats cost{ static_cast(done.milliseconds), static_cast(done.cpuMilliseconds), static_cast(done.memoryEstimate / 1024) }; @@ -495,6 +509,7 @@ void UgcProcessor::Collect() { Record(done); continue; } + if (done.outcome.ok && done.iconChangeMs != 0.0) RecordIconTime(done.id, done.iconChangeMs); m_Log.push_back({ Kind::MODEL, done.id, done.outcome.ok, done.milliseconds, done.outcome.ok ? "icon drawn again" : done.outcome.error, UnixNow() }); while (m_Log.size() > LOG_LENGTH) m_Log.pop_front(); continue; diff --git a/dUgcServer/Processing/UgcProcessor.h b/dUgcServer/Processing/UgcProcessor.h index 9ec5be119..d283d3f5d 100644 --- a/dUgcServer/Processing/UgcProcessor.h +++ b/dUgcServer/Processing/UgcProcessor.h @@ -197,6 +197,7 @@ private: double cpuMilliseconds{}; // the worker thread's CPU time for it uint64_t memoryEstimate{}; // the bytes it was estimated to need (the memory budget's figure) bool iconOnly{}; + double iconChangeMs{}; // an icon drawn again: how much longer it took than the icon made before std::vector checksums; // of the files written that the client downloads as sd0 }; @@ -217,6 +218,8 @@ private: UgcIconParams::Values IconValues(const std::string& kind, const std::string& itemTarget); void Collect(); void Record(const Done& done); + // Main thread: a model whose icon was drawn again took `changeMs` longer to make (its icon's share of the make) + void RecordIconTime(LWOOBJID id, double changeMs); void Worker(); void SampleUsage(); diff --git a/docs/UgcServer.md b/docs/UgcServer.md index dd48e8042..beba256c6 100644 --- a/docs/UgcServer.md +++ b/docs/UgcServer.md @@ -544,7 +544,10 @@ first, then as a build through its combination. Migrations `dlu/mysql/90_ugc_process_time.sql`, `91_ugc_process_diagnostics.sql` and `dlu/sqlite/73`, `74`: `ugc.process_ms` (wall time of the last make), `ugc.process_cpu_ms` (the worker thread's CPU time) and `ugc.process_memory_kb` (the estimated memory it needed), and the same on `ugc_modular_build`; the dashboard's Took, -CPU and RAM (est.) columns. +CPU and RAM (est.) columns. A make's time includes its icon's. When only a model's icon is drawn again (the icon +editor's Draw all icons of this type again), its `stats.json` gets the new icon's time (`ms.icon`, and `ms.total` +changed by the difference) and `process_ms` and `process_cpu_ms` change by the same difference (the icon is drawn on +one thread, so its time is taken as its CPU time). Migrations `dlu/mysql/92_ugc_triangles_before.sql` and `dlu/sqlite/75_ugc_triangles_before.sql`: `ugc.triangle_count_before`, LOD 0's triangles before hidden faces were removed (the dashboard's Saved column). diff --git a/tests/dUgcTests/UgcTests.cpp b/tests/dUgcTests/UgcTests.cpp index 3b25e9338..e08277a73 100644 --- a/tests/dUgcTests/UgcTests.cpp +++ b/tests/dUgcTests/UgcTests.cpp @@ -1962,3 +1962,21 @@ TEST(UgcFormats, TransparentShapesHaveTheGamesAlphaMaterial) { const auto opaqueAlphas = alphaOf(opaque); EXPECT_EQ(std::find(opaqueAlphas.begin(), opaqueAlphas.end(), 0.9999f), opaqueAlphas.end()); } + +// An icon drawn again keeps the make's time with its icon's: ms.icon is the new one's, ms.total changes by the difference +TEST(UgcJobs, IconDrawnAgainChangesTheMakesTime) { + double change = 0.0; + const auto updated = UgcJobs::WithIconTime(R"({"bricks":3,"ms":{"build":100,"icon":40,"total":500}})", 70.4, change); + ASSERT_TRUE(updated); + const auto stats = nlohmann::json::parse(*updated); + EXPECT_EQ(stats["ms"]["icon"], 70); + EXPECT_EQ(stats["ms"]["total"], 530); + EXPECT_EQ(stats["ms"]["build"], 100); + EXPECT_EQ(stats["bricks"], 3); + EXPECT_NEAR(change, 30.4, 1e-9); + // Stats from before the icon was timed: all of the new icon's time is added + const auto old = UgcJobs::WithIconTime(R"({"ms":{"total":500}})", 20.0, change); + ASSERT_TRUE(old); + EXPECT_EQ(nlohmann::json::parse(*old)["ms"]["total"], 520); + EXPECT_FALSE(UgcJobs::WithIconTime("not json", 20.0, change)); +}