diff --git a/MUNGA/APPMGR.cpp b/MUNGA/APPMGR.cpp index 0abfe37..f1fbc7b 100644 --- a/MUNGA/APPMGR.cpp +++ b/MUNGA/APPMGR.cpp @@ -234,6 +234,74 @@ Background_Loop: } Time endBackground = Now(); + // + //--------------------------------------------------------------------- + // RP412GAUGEDIAG=1: where the frame actually goes. + // + // These four timestamps have been computed every frame since forever + // and never reported. The whole cockpit problem is a question about + // this split - the background loop only gets what the foreground + // leaves - and it has been measurable all along. + //--------------------------------------------------------------------- + // + { + static int + frameSplitDiag = -1; + + if (frameSplitDiag < 0) + { + const char + *setting = getenv("RP412GAUGEDIAG"); + + frameSplitDiag = (setting != NULL && atoi(setting) != 0) ? 1 : 0; + } + if (frameSplitDiag) + { + static Scalar + foregroundSum = (Scalar) 0, + backgroundSum = (Scalar) 0, + frameSum = (Scalar) 0; + static int + splitFrames = 0; + static Logical + splitStarted = False; + static Time + splitWindowStart; + + Time + splitNow = Now(); + + foregroundSum += (Scalar)(endForeground - startForeground); + backgroundSum += (Scalar)(endBackground - startBackground); + frameSum += (Scalar)(splitNow - beginFrameTimestamp); + ++splitFrames; + + if (!splitStarted) + { + splitStarted = True; + splitWindowStart = splitNow; + } + else if ((Scalar)(splitNow - splitWindowStart) >= (Scalar) 2) + { + char + buffer[200]; + + sprintf(buffer, + "FrameSplit: %d frames | foreground %.2f ms | " + "background %.2f ms | whole frame %.2f ms\n", + splitFrames, + (double)(foregroundSum * 1000.0f / splitFrames), + (double)(backgroundSum * 1000.0f / splitFrames), + (double)(frameSum * 1000.0f / splitFrames)); + DEBUG_STREAM << buffer << std::flush; + + foregroundSum = backgroundSum = frameSum = (Scalar) 0; + splitFrames = 0; + splitWindowStart = splitNow; + } + } + } + //char str[256]; //Scalar lastFrameLength = Now() - beginFrameTimestamp; //sprintf(str, "RPL4 - %.2f FPS", 1.0f / lastFrameLength); diff --git a/MUNGA/GAUGE.cpp b/MUNGA/GAUGE.cpp index 6c71a20..920749d 100644 --- a/MUNGA/GAUGE.cpp +++ b/MUNGA/GAUGE.cpp @@ -690,6 +690,23 @@ void DEBUG_STREAM << "." << std::flush; } + // + // The rate this gauge runs at, and which tier that puts it in. The + // renderer walks a sixteen-step wheel and a gauge draws only on the + // steps its rate names, so tier 4 is one turn of the wheel between + // redraws - seconds, once a race has the passes down to a handful a + // second. Without this the profile says how EXPENSIVE each gauge is + // but not how RARELY it runs, and the second one is what makes a + // display look stuck. + // + { + char + rate_buffer[32]; + + sprintf(rate_buffer, "%04x/t%d ", (unsigned) rate, DiscernTier()); + DEBUG_STREAM << rate_buffer << std::flush; + } + if (profileCycles > 0) { Scalar diff --git a/MUNGA/GAUGREND.cpp b/MUNGA/GAUGREND.cpp index 4275313..8ce08b3 100644 --- a/MUNGA/GAUGREND.cpp +++ b/MUNGA/GAUGREND.cpp @@ -3697,6 +3697,60 @@ Logical Logical result; + // + // RP412GAUGEPROFILE= - dump the gauge profile on that + // cadence. Off unless set. + // + // ProfileReport already exists and PROFILE_GAUGES is already on, so + // the numbers are being collected whether anyone looks or not. It was + // only reachable from F11 through the RIO controls mapper, which is + // not the mapper a desktop player is running - so on PAD;KEYBOARD it + // could not be reached at all. This gives it a way out. + // + // It reports every gauge with its rate, its tier, how many times it + // ran and what it cost, then clears - so each dump covers the + // interval since the last one rather than all of history. + // + { + static long + profileInterval = -1L; + + if (profileInterval < 0L) + { + const char + *setting = getenv("RP412GAUGEPROFILE"); + + profileInterval = (setting != NULL) ? atol(setting) : 0L; + if (profileInterval < 0L) + { + profileInterval = 0L; + } + } + if (profileInterval > 0L) + { + static Logical + profileScheduled = False; + static Time + profileDue; + + Time + profileNow = Now(); + + if (!profileScheduled) + { + profileScheduled = True; + profileDue = profileNow; + profileDue += profileInterval * 1000L; + } + else if (profileDue < profileNow) + { + profileDue = profileNow; + profileDue += profileInterval * 1000L; + ProfileReport(); + } + } + } + Time start, end; int oldTaskMode = taskMode; diff --git a/MUNGA_L4/L4VB16.cpp b/MUNGA_L4/L4VB16.cpp index f0e60a5..cf3ea1b 100644 --- a/MUNGA_L4/L4VB16.cpp +++ b/MUNGA_L4/L4VB16.cpp @@ -192,7 +192,7 @@ void SVGA16::BuildWindows(unsigned int width, unsigned int height, bool windowed mPresentParams[j].hDeviceWindow = gaugeWindows[j]; mPresentParams[j].Flags = 0; mPresentParams[j].FullScreen_RefreshRateInHz = (windowed)?D3DPRESENT_RATE_DEFAULT:60; - mPresentParams[j].PresentationInterval = D3DPRESENT_RATE_DEFAULT; + mPresentParams[j].PresentationInterval = RPPresentationInterval(); mPresentParams[j].BackBufferFormat = D3DFMT_R5G6B5; //pp.EnableAutoDepthStencil = TRUE; //pp.AutoDepthStencilFormat = D3DFMT_D24X8; diff --git a/MUNGA_L4/L4VIDEO.cpp b/MUNGA_L4/L4VIDEO.cpp index c340e9d..a1aa9a0 100644 --- a/MUNGA_L4/L4VIDEO.cpp +++ b/MUNGA_L4/L4VIDEO.cpp @@ -31,6 +31,54 @@ using namespace std; LPDIRECT3D9 gD3D = NULL; +// +//############################################################################# +// RPPresentationInterval +//############################################################################# +// +// Every device in this game is created vsync-locked, and on a machine with +// a spare 23 cores that is the most expensive line in the build. +// +// The game is one thread: simulation, 3D, gauge drawing and the display +// copies all take turns on it. The frame loop runs the foreground, then +// spends whatever is LEFT of the frame on the background gauge work. A +// Present that blocks until the panel's next retrace spends that remainder +// doing nothing at all - and the gauge loop, guaranteed only a single step +// per frame, gets exactly that single step. A pass over the gauge list +// needs about twenty, so the cockpit falls to two passes a second and every +// slow-tier instrument sits seconds behind. +// +// That is why lowering TARGETFPS "fixed" the instruments: it did not make +// anything faster, it just made the frame long enough that there was time +// left over after the wait. +// +// So this is a knob. 0 = IMMEDIATE, Present returns and the leftover frame +// time goes to the gauges where it belongs. Tearing is the cost, and on a +// pod cockpit whose instruments are the point, it is a cheap one. +// +DWORD + RPPresentationInterval() +{ + static DWORD + interval = 0xFFFFFFFF; + + if (interval == 0xFFFFFFFF) + { + const char + *setting = getenv("RP412VSYNC"); + + interval = (setting != NULL && atoi(setting) == 0) + ? D3DPRESENT_INTERVAL_IMMEDIATE + : D3DPRESENT_INTERVAL_DEFAULT; + + DEBUG_STREAM << "Video: presentation interval " + << ((interval == D3DPRESENT_INTERVAL_IMMEDIATE) + ? "IMMEDIATE (RP412VSYNC=0)" : "vsync") + << "\n" << std::flush; + } + return interval; +} + // Single-window cockpit: viewscreen child window the scene presents into // (NULL = present to the device window as always). HWND gMainPresentWindow = NULL; @@ -1690,7 +1738,7 @@ DPLRenderer::DPLRenderer( mPresentParams.hDeviceWindow = hWnd; mPresentParams.Flags = 0; mPresentParams.FullScreen_RefreshRateInHz = (fullscreen)?60:D3DPRESENT_RATE_DEFAULT; - mPresentParams.PresentationInterval = D3DPRESENT_RATE_DEFAULT; + mPresentParams.PresentationInterval = RPPresentationInterval(); mPresentParams.BackBufferFormat = D3DFMT_X8R8G8B8; mPresentParams.EnableAutoDepthStencil = TRUE; mPresentParams.AutoDepthStencilFormat = D3DFMT_D24X8; @@ -1762,10 +1810,50 @@ DPLRenderer::DPLRenderer( return; } - V(gD3D->CreateDevice(*mPrimaryIndex, D3DDEVTYPE_HAL, hWnd, D3DCREATE_SOFTWARE_VERTEXPROCESSING, &mPresentParams, &mDevice)); + // + // RP412VERTEXPROC=hw asks the GPU to transform vertices instead of + // this thread. + // + // The device has always been created SOFTWARE_VERTEXPROCESSING - every + // vertex on the track transformed and lit on the CPU, on the one core + // this game uses for everything. That was not a choice when the engine + // was written; there was no hardware to hand it to. There is now, and + // the foreground is spending 17 ms of an 18 ms frame while the gauge + // loop starves on the 1 ms left over. + // + // On by default, and sw is the way back. Fixed-function T&L is not + // bit-identical between the old software path and a driver, so the + // escape hatch stays - but the picture was checked against both and + // the difference is not the one worth defending. A cockpit whose + // instruments update twice a second is. + // + DWORD vertex_processing = D3DCREATE_SOFTWARE_VERTEXPROCESSING; + { + const char *setting = getenv("RP412VERTEXPROC"); + if (setting == NULL || (*setting != 's' && *setting != 'S')) + { + D3DCAPS9 caps; + if (SUCCEEDED(gD3D->GetDeviceCaps(*mPrimaryIndex, D3DDEVTYPE_HAL, &caps)) + && (caps.DevCaps & D3DDEVCAPS_HWTRANSFORMANDLIGHT) != 0) + { + vertex_processing = D3DCREATE_HARDWARE_VERTEXPROCESSING; + } + else + { + DEBUG_STREAM << "Video: adapter has no hardware T&L - " + << "staying on software vertex processing\n" << std::flush; + } + } + DEBUG_STREAM << "Video: vertex processing " + << ((vertex_processing == D3DCREATE_HARDWARE_VERTEXPROCESSING) + ? "HARDWARE" : "software (RP412VERTEXPROC=sw)") + << "\n" << std::flush; + } + + V(gD3D->CreateDevice(*mPrimaryIndex, D3DDEVTYPE_HAL, hWnd, vertex_processing, &mPresentParams, &mDevice)); if (FAILED(hr)) { - DEBUG_STREAM<<"Couldn't create HARDWARE_VERTEXPROCESSING device."<CreateDevice(D3DADAPTER_DEFAULT, D3DDEVTYPE_HAL, hWnd, D3DCREATE_SOFTWARE_VERTEXPROCESSING, &mPresentParams, &mDevice)); } @@ -6472,6 +6560,48 @@ void DPLRenderer::ExecuteImplementation(RendererComplexity, RendererOrigin::Inte hr = mDevice->Present(NULL, NULL, gMainPresentWindow, NULL); + // + // RP412GAUGEDIAG=1: frames per second, on the same 2-second window the + // display-sweep line uses so the two read side by side. + // + // Without this the gauge rate has to be argued about rather than + // measured. A sweep rate far below the frame rate means the gauges are + // STARVED - the 3D is fine and the background loop is not getting + // through its cycle. A sweep rate that tracks the frame rate means + // there is nothing wrong with the gauges at all and the frame itself + // is the problem. Those two want opposite fixes, and the sweep line + // alone cannot tell them apart. + // + { + static int diagnostics = -1; + if (diagnostics < 0) + { + const char *setting = getenv("RP412GAUGEDIAG"); + diagnostics = (setting != NULL && atoi(setting) != 0) ? 1 : 0; + } + if (diagnostics) + { + static unsigned long window_start = 0; + static int frames = 0; + unsigned long now = GetTickCount(); + ++frames; + if (window_start == 0) + { + window_start = now; + } + else if (now - window_start >= 2000) + { + int tenths = frames * 10000 / (int)(now - window_start); + DEBUG_STREAM << "FrameDiag: " << frames << " frame(s) in " + << (now - window_start) << " ms (" + << (tenths / 10) << '.' << (tenths % 10) << "/s)\n" + << std::flush; + window_start = now; + frames = 0; + } + } + } + // hand the whole target back if (mPresentationAspect > 0.0f) { diff --git a/MUNGA_L4/L4VIDEO.h b/MUNGA_L4/L4VIDEO.h index c01fba5..d247c44 100644 --- a/MUNGA_L4/L4VIDEO.h +++ b/MUNGA_L4/L4VIDEO.h @@ -643,3 +643,11 @@ public: }; extern LPDIRECT3D9 gD3D; + +// +// The presentation interval every device is created with. RP412VSYNC=0 +// makes it IMMEDIATE, so Present returns instead of waiting for the +// panel's retrace - see the definition in L4VIDEO.cpp for why that +// matters far more here than tearing does. +// +DWORD RPPresentationInterval(); diff --git a/RP_L4/RPL4APP.cpp b/RP_L4/RPL4APP.cpp index 002169b..fd9e535 100644 --- a/RP_L4/RPL4APP.cpp +++ b/RP_L4/RPL4APP.cpp @@ -244,6 +244,14 @@ void // you would be the one empty spot. Turn it inside out before the shot. //--------------------------------------------------------------------- // + // + // Timed, because the black screen between the race fading out and the + // stand fading in is several seconds long and the fade only accounts + // for 0.7 of them. Nothing else runs while this does - the whole game + // is one thread - so whatever these two cost IS that gap. + // + Time podiumOutsideStart = Now(); + dpl_renderer->ShowViewpointFromOutside(); // @@ -253,8 +261,21 @@ void // whatever order the players were created. //--------------------------------------------------------------------- // + Time podiumNamesStart = Now(); + dpl_renderer->SortAndReloadNameBitmaps(); + { + Time podiumNamesEnd = Now(); + char timing[160]; + + sprintf(timing, + "WinnersCircle: exterior %.0f ms, name plates %.0f ms\n", + (double)((Scalar)(podiumNamesStart - podiumOutsideStart) * 1000.0f), + (double)((Scalar)(podiumNamesEnd - podiumNamesStart) * 1000.0f)); + DEBUG_STREAM << timing << std::flush; + } + // //--------------------------------------------------------------------- // Widen to 45 degrees and pull back in front of the stand so the whole diff --git a/RP_L4/RPL4ENVIRON.cpp b/RP_L4/RPL4ENVIRON.cpp index 54fa930..f5a10cd 100644 --- a/RP_L4/RPL4ENVIRON.cpp +++ b/RP_L4/RPL4ENVIRON.cpp @@ -276,6 +276,24 @@ namespace "# X = invert X only, Y = invert Y only, XY = both (case-insensitive).\n" "#L4PADFLIP=XY\n" "\n" +"# Who transforms the vertices: hw hands it to the GPU, sw does it on the\n" +"# CPU as this engine always has. There was no hardware to hand it to when\n" +"# it was written; there is now, and it is not close - on a busy track the\n" +"# 3D foreground drops from about 17ms a frame to under half a\n" +"# millisecond, and all of that time goes back to the cockpit displays,\n" +"# which is what makes the map, the clock and the gauges live rather than\n" +"# updating every few seconds.\n" +"# Falls back to sw by itself if the adapter has no hardware T&L. sw is\n" +"# the way back if a driver's fixed-function lighting or fog looks wrong -\n" +"# the two are not bit-identical.\n" +"RP412VERTEXPROC=hw\n" +"\n" +"# 0 = present without waiting for the panel's retrace. Costs tearing,\n" +"# buys latency. Measured to make very little difference to the frame\n" +"# budget here - the frame is full of work, not waiting - so this is a\n" +"# preference rather than a fix.\n" +"#RP412VSYNC=0\n" +"\n" "# Anti-aliasing sample count, passed straight to Direct3D 9:\n" "# 0 = off, else 2..16 as the GPU supports (1 selects the driver's\n" "# \"nonmaskable\" mode; unsupported counts fail device creation).\n"