Skip to content

Commit 9e76d65

Browse files
markgalvan-intelmarkgalvan-intel
committed
Manual merge of metric and gather functions. Fixed all build errors for Intel PresentMon.
1 parent f84a0ad commit 9e76d65

File tree

8 files changed

+111
-52
lines changed

8 files changed

+111
-52
lines changed

‎IntelPresentMon/PresentMonAPI2Tests/CsvHelper.h‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -321,7 +321,7 @@ class CsvParser {
321321
bool Open(std::wstring const& path, uint32_t processId);
322322
void Close();
323323
bool VerifyBlobAgainstCsv(const std::string& processName, const unsigned int& processId,
324-
PM_QUERY_ELEMENT(&queryElements)[19], pmapi::BlobContainer& blobs);
324+
PM_QUERY_ELEMENT(&queryElements)[20], pmapi::BlobContainer& blobs);
325325
bool ResetCsv();
326326

327327
private:
@@ -350,7 +350,7 @@ CsvParser::CsvParser()
350350
{}
351351

352352
bool CsvParser::VerifyBlobAgainstCsv(const std::string& processName, const unsigned int& processId,
353-
PM_QUERY_ELEMENT(&queryElements)[19], pmapi::BlobContainer& blobs)
353+
PM_QUERY_ELEMENT(&queryElements)[20], pmapi::BlobContainer& blobs)
354354
{
355355

356356
for (auto pBlob : blobs) {

‎IntelPresentMon/PresentMonAPI2Tests/EtlTests.cpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -480,7 +480,7 @@ namespace EtlTests
480480
goldCsvFile.Open(goldCsvName, processId);
481481

482482
oChild.emplace("PresentMonService.exe"s,
483-
"--timed-stop"s, "10000"s,
483+
//"--timed-stop"s, "10000"s,
484484
"--control-pipe"s, pipeName,
485485
"--nsm-prefix"s, "pmon_nsm_utest_"s,
486486
"--intro-nsm"s, introName,

‎IntelPresentMon/PresentMonMiddleware/ConcreteMiddleware.cpp‎

Lines changed: 33 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -564,7 +564,6 @@ static void ReportMetricsHelper(
564564
FrameMetrics metrics;
565565
metrics.mCPUStart = chain->mLastPresent.PresentStartTime + chain->mLastPresent.TimeInPresent;
566566

567-
@@@ Merge in fixes from GameTechDev/main
568567
if (displayIndex == appIndex) {
569568
msGPUDuration = pmSession.TimestampDeltaToUnsignedMilliSeconds(p->GPUStartTime, p->ReadyTime);
570569
metrics.mCPUBusy = pmSession.TimestampDeltaToUnsignedMilliSeconds(metrics.mCPUStart, p->PresentStartTime);
@@ -590,19 +589,41 @@ static void ReportMetricsHelper(
590589
metrics.mDisplayedTime = 0;
591590
}
592591

593-
if (displayed && displayIndex == appIndex && p->InputTime != 0) {
594-
metrics.mClickToPhotonLatency = pmSession.TimestampDeltaToUnsignedMilliSeconds(p->InputTime, screenTime);
592+
if (displayIndex == appIndex) {
593+
if (displayed) {
594+
auto updatedInputTime = chain->mLastReceivedNotDisplayedAllInputTime == 0 ? 0 :
595+
pmSession.TimestampDeltaToUnsignedMilliSeconds(chain->mLastReceivedNotDisplayedAllInputTime, screenTime);
596+
metrics.mAllInputPhotonLatency = p->InputTime == 0 ? updatedInputTime :
597+
pmSession.TimestampDeltaToUnsignedMilliSeconds(p->InputTime, screenTime);
598+
599+
updatedInputTime = chain->mLastReceivedNotDisplayedMouseClickTime == 0 ? 0 :
600+
pmSession.TimestampDeltaToUnsignedMilliSeconds(chain->mLastReceivedNotDisplayedMouseClickTime, screenTime);
601+
metrics.mClickToPhotonLatency = p->MouseClickTime == 0 ? updatedInputTime :
602+
pmSession.TimestampDeltaToUnsignedMilliSeconds(p->MouseClickTime, screenTime);
603+
604+
chain->mLastReceivedNotDisplayedAllInputTime = 0;
605+
chain->mLastReceivedNotDisplayedMouseClickTime = 0;
606+
}
607+
else {
608+
metrics.mClickToPhotonLatency = 0;
609+
metrics.mAllInputPhotonLatency = 0;
610+
if (p->InputTime != 0) {
611+
chain->mLastReceivedNotDisplayedAllInputTime = p->InputTime;
612+
}
613+
if (p->MouseClickTime != 0) {
614+
chain->mLastReceivedNotDisplayedMouseClickTime = p->MouseClickTime;
615+
}
616+
}
595617
} else {
596618
metrics.mClickToPhotonLatency = 0;
619+
metrics.mAllInputPhotonLatency = 0;
597620
}
598621

599622
if (displayed && displayIndex == appIndex && chain->mLastDisplayedCPUStart != 0) {
600623
metrics.mAnimationError = pmSession.TimestampDeltaToMilliSeconds(screenTime - chain->mLastDisplayedScreenTime,
601624
metrics.mCPUStart - chain->mLastDisplayedCPUStart);
602-
metrics.mAnimationErrorValid = true;
603625
} else {
604626
metrics.mAnimationError = 0;
605-
metrics.mAnimationErrorValid = false;
606627
}
607628

608629
if (p->DisplayedCount == 0) {
@@ -636,8 +657,13 @@ static void ReportMetricsHelper(
636657
}
637658
}
638659

639-
if (displayed && displayIndex == appIndex && p->InputTime != 0) {
640-
chain->mClickToPhotonLatency.push_back(metrics.mClickToPhotonLatency);
660+
if (displayed && displayIndex == appIndex) {
661+
if (metrics.mAllInputPhotonLatency != 0) {
662+
chain->mAllInputToPhotonLatency.push_back(metrics.mAllInputPhotonLatency);
663+
}
664+
if (metrics.mClickToPhotonLatency != 0) {
665+
chain->mClickToPhotonLatency.push_back(metrics.mClickToPhotonLatency);
666+
}
641667
}
642668

643669
if (metrics.mAnimationErrorValid) {

‎IntelPresentMon/PresentMonMiddleware/FrameEventQuery.cpp‎

Lines changed: 61 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -124,7 +124,7 @@ namespace
124124
outputPaddingSize_ = (uint16_t)util::GetPadding(nextAvailableByteOffset, alignof(FrameType));
125125
outputOffset_ = uint32_t(nextAvailableByteOffset) + outputPaddingSize_;
126126
}
127-
void Gather(const Context& ctx, uint8_t* pDestBlob) const override
127+
void Gather(Context& ctx, uint8_t* pDestBlob) const override
128128
{
129129
auto val = ctx.pSourceFrameData->present_event.Displayed_FrameType[ctx.sourceFrameDisplayIndex];
130130
// Currently not reporting out not set or repeated frames.
@@ -238,7 +238,7 @@ namespace
238238
outputPaddingSize_ = (uint16_t)util::GetPadding(nextAvailableByteOffset, alignof(double));
239239
outputOffset_ = uint32_t(nextAvailableByteOffset) + outputPaddingSize_;
240240
}
241-
void Gather(const Context& ctx, uint8_t* pDestBlob) const override
241+
void Gather(Context& ctx, uint8_t* pDestBlob) const override
242242
{
243243
if (ctx.dropped) {
244244
reinterpret_cast<double&>(pDestBlob[outputOffset_]) =
@@ -406,7 +406,7 @@ namespace
406406
outputPaddingSize_ = (uint16_t)util::GetPadding(nextAvailableByteOffset, alignof(double));
407407
outputOffset_ = uint32_t(nextAvailableByteOffset) + outputPaddingSize_;
408408
}
409-
void Gather(const Context& ctx, uint8_t* pDestBlob) const override
409+
void Gather(Context& ctx, uint8_t* pDestBlob) const override
410410
{
411411
if (ctx.dropped) {
412412
reinterpret_cast<double&>(pDestBlob[outputOffset_]) =
@@ -591,7 +591,7 @@ namespace
591591
private:
592592
uint32_t outputOffset_;
593593
};
594-
template<uint64_t PmNsmPresentEvent::* pStart, uint64_t PmNsmPresentEvent::* pEnd, bool doDroppedCheck, bool isMouseClick>
594+
template<uint64_t PmNsmPresentEvent::* pStart, bool doDroppedCheck, bool isMouseClick>
595595
class InputLatencyGatherCommand_ : public pmon::mid::GatherCommand_
596596
{
597597
public:
@@ -612,25 +612,29 @@ namespace
612612

613613
double updatedInputTime = 0.;
614614
double val = 0.;
615-
if (isMouseClick) {
616-
updatedInputTime = ctx.lastReceivedNotDisplayedClickQpc == 0 ? 0. :
617-
TimestampDeltaToUnsignedMilliSeconds(ctx.lastReceivedNotDisplayedClickQpc,
618-
ctx.pSourceFrameData->present_event.*pEnd, ctx.performanceCounterPeriodMs);
619-
val = ctx.pSourceFrameData->present_event.*pStart == 0 ? updatedInputTime :
620-
TimestampDeltaToUnsignedMilliSeconds(ctx.pSourceFrameData->present_event.*pStart,
621-
ctx.pSourceFrameData->present_event.*pEnd,
622-
ctx.performanceCounterPeriodMs);
623-
ctx.lastReceivedNotDisplayedClickQpc = 0;
624-
}
625-
else {
626-
updatedInputTime = ctx.lastReceivedNotDisplayedAllInputTime == 0 ? 0. :
627-
TimestampDeltaToUnsignedMilliSeconds(ctx.lastReceivedNotDisplayedAllInputTime,
628-
ctx.pSourceFrameData->present_event.*pEnd, ctx.performanceCounterPeriodMs);
629-
val = ctx.pSourceFrameData->present_event.*pStart == 0 ? updatedInputTime :
630-
TimestampDeltaToUnsignedMilliSeconds(ctx.pSourceFrameData->present_event.*pStart,
631-
ctx.pSourceFrameData->present_event.*pEnd,
632-
ctx.performanceCounterPeriodMs);
633-
ctx.lastReceivedNotDisplayedAllInputTime = 0;
615+
if (ctx.sourceFrameDisplayIndex == ctx.appIndex) {
616+
if (isMouseClick) {
617+
updatedInputTime = ctx.lastReceivedNotDisplayedClickQpc == 0 ? 0. :
618+
TimestampDeltaToUnsignedMilliSeconds(ctx.lastReceivedNotDisplayedClickQpc,
619+
ctx.pSourceFrameData->present_event.Displayed_ScreenTime[ctx.sourceFrameDisplayIndex],
620+
ctx.performanceCounterPeriodMs);
621+
val = ctx.pSourceFrameData->present_event.*pStart == 0 ? updatedInputTime :
622+
TimestampDeltaToUnsignedMilliSeconds(ctx.pSourceFrameData->present_event.*pStart,
623+
ctx.pSourceFrameData->present_event.Displayed_ScreenTime[ctx.sourceFrameDisplayIndex],
624+
ctx.performanceCounterPeriodMs);
625+
ctx.lastReceivedNotDisplayedClickQpc = 0;
626+
}
627+
else {
628+
updatedInputTime = ctx.lastReceivedNotDisplayedAllInputTime == 0 ? 0. :
629+
TimestampDeltaToUnsignedMilliSeconds(ctx.lastReceivedNotDisplayedAllInputTime,
630+
ctx.pSourceFrameData->present_event.Displayed_ScreenTime[ctx.sourceFrameDisplayIndex],
631+
ctx.performanceCounterPeriodMs);
632+
val = ctx.pSourceFrameData->present_event.*pStart == 0 ? updatedInputTime :
633+
TimestampDeltaToUnsignedMilliSeconds(ctx.pSourceFrameData->present_event.*pStart,
634+
ctx.pSourceFrameData->present_event.Displayed_ScreenTime[ctx.sourceFrameDisplayIndex],
635+
ctx.performanceCounterPeriodMs);
636+
ctx.lastReceivedNotDisplayedAllInputTime = 0;
637+
}
634638
}
635639

636640
if (val == 0.) {
@@ -834,9 +838,9 @@ std::unique_ptr<mid::GatherCommand_> PM_FRAME_QUERY::MapQueryElementToGatherComm
834838
case PM_METRIC_DISPLAY_LATENCY:
835839
return std::make_unique<DisplayLatencyGatherCommand_>(pos);
836840
case PM_METRIC_CLICK_TO_PHOTON_LATENCY:
837-
return std::make_unique<InputLatencyGatherCommand_<&Pre::MouseClickTime, &Pre::ScreenTime, 1, 1>>(pos);
841+
return std::make_unique<InputLatencyGatherCommand_<&Pre::MouseClickTime, 1, 1>>(pos);
838842
case PM_METRIC_ALL_INPUT_TO_PHOTON_LATENCY:
839-
return std::make_unique<InputLatencyGatherCommand_<&Pre::InputTime, &Pre::ScreenTime, 1, 0>>(pos);
843+
return std::make_unique<InputLatencyGatherCommand_<&Pre::InputTime, 1, 0>>(pos);
840844

841845
default:
842846
pmlog_error("unknown metric id").pmwatch((int)q.metric).diag();
@@ -851,11 +855,35 @@ void PM_FRAME_QUERY::Context::UpdateSourceData(const PmNsmFrameData* pSourceFram
851855
const PmNsmFrameData* pPreviousFrameDataOfLastDisplayed)
852856
{
853857
pSourceFrameData = pSourceFrameData_in;
854-
@@@ do manual merge from GameTechDev/main
855-
sourceFrameDisplayIndex = 0;
858+
sourceFrameDisplayIndex = 0;
856859
dropped = pSourceFrameData->present_event.FinalState != PresentResult::Presented && pSourceFrameData->present_event.DisplayedCount == 0;
857-
cpuStart = pFrameDataOfLastPresented->present_event.PresentStartTime + pFrameDataOfLastPresented->present_event.TimeInPresent;
858-
nextDisplayedQpc = pFrameDataOfNextDisplayed->present_event.Displayed_ScreenTime[0];
860+
if (dropped) {
861+
if (pSourceFrameData->present_event.MouseClickTime != 0) {
862+
lastReceivedNotDisplayedClickQpc = pSourceFrameData->present_event.MouseClickTime;
863+
}
864+
if (pSourceFrameData->present_event.InputTime != 0) {
865+
lastReceivedNotDisplayedAllInputTime = pSourceFrameData->present_event.InputTime;
866+
}
867+
}
868+
869+
if (pFrameDataOfLastPresented) {
870+
cpuStart = pFrameDataOfLastPresented->present_event.PresentStartTime + pFrameDataOfLastPresented->present_event.TimeInPresent;
871+
}
872+
else {
873+
// TODO: log issue or invalidate related columns or drop frame (or some combination)
874+
pmlog_info("null pFrameDataOfLastPresented");
875+
cpuStart = 0;
876+
}
877+
878+
if (pFrameDataOfNextDisplayed) {
879+
nextDisplayedQpc = pFrameDataOfNextDisplayed->present_event.Displayed_ScreenTime[0];
880+
}
881+
else {
882+
// TODO: log issue or invalidate related columns or drop frame (or some combination)
883+
pmlog_info("null pFrameDataOfNextDisplayed");
884+
nextDisplayedQpc = 0;
885+
}
886+
859887
if (pFrameDataOfLastDisplayed && pFrameDataOfLastDisplayed->present_event.DisplayedCount > 0) {
860888
previousDisplayedQpc = pFrameDataOfLastDisplayed->present_event.Displayed_ScreenTime[pFrameDataOfLastDisplayed->present_event.DisplayedCount - 1];
861889
}
@@ -864,10 +892,13 @@ void PM_FRAME_QUERY::Context::UpdateSourceData(const PmNsmFrameData* pSourceFram
864892
pmlog_info("null pFrameDataOfLastDisplayed");
865893
previousDisplayedQpc = 0;
866894
}
895+
867896
if (pPreviousFrameDataOfLastDisplayed) {
868-
previousDisplayedCpuStartQpc = pPreviousFrameDataOfLastDisplayed->present_event.PresentStartTime + pPreviousFrameDataOfLastDisplayed->present_event.TimeInPresent;
897+
previousDisplayedCpuStartQpc = pPreviousFrameDataOfLastDisplayed->present_event.PresentStartTime +
898+
pPreviousFrameDataOfLastDisplayed->present_event.TimeInPresent;
869899
}
870900
else {
901+
pmlog_info("null pPreviousFrameDataOfLastDisplayed");
871902
previousDisplayedCpuStartQpc = 0;
872903
}
873904
appIndex = 0;

‎IntelPresentMon/PresentMonService/CliOptions.h‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,5 @@ namespace clio
3434

3535
static constexpr const char* description = "Intel PresentMon service for frame and system performance measurement";
3636
static constexpr const char* name = "PresentMonService.exe";
37-
private:
38-
CLI::CheckedTransformer logLevelTf_{ GetLevelMapNarrow(), CLI::ignore_case };
3937
};
4038
}

‎IntelPresentMon/PresentMonService/RealtimePresentMonSession.cpp‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -231,7 +231,9 @@ void RealtimePresentMonSession::AddPresents(
231231
if (p->FinalState == PresentResult::Presented) {
232232
const auto per = util::GetTimestampPeriodSeconds();
233233
const auto now = util::GetCurrentTimestamp();
234-
const auto lag = util::TimestampDeltaToSeconds(p->ScreenTime, now, per);
234+
// TODO: Presents can now have multiple displayed frames if we are tracking
235+
// frame types. For now take the first displayed frame for logging stats
236+
const auto lag = util::TimestampDeltaToSeconds(p->Displayed[0].second, now, per);
235237
pmlog_verb(svc::v::etwq)(std::format("Frame [{}] lag: {} ms", p->FrameId, lag * 1000.));
236238
}
237239
}

‎IntelPresentMon/PresentMonUtils/StreamFormat.h‎

Lines changed: 11 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -63,16 +63,14 @@ struct PmNsmPresentEvent
6363
uint32_t ProcessId; // ID of the process that presented
6464
uint32_t ThreadId; // ID of the thread that presented
6565
uint64_t TimeInPresent; // QPC duration between runtime present start and end
66-
uint64_t GPUStartTime; // QPC value when the frame's first DMA packet started
67-
uint64_t ReadyTime; // QPC value when the frame's last DMA packet completed
66+
uint64_t GPUStartTime; // QPC value when the frame's first DMA packet started
67+
uint64_t ReadyTime; // QPC value when the frame's last DMA packet completed
6868

69-
uint64_t GPUDuration; // QPC duration during which a frame's DMA packet was
70-
// running on any node
69+
uint64_t GPUDuration; // QPC duration during which a frame's DMA packet was
70+
// running on any node
7171
uint64_t
72-
GPUVideoDuration; // QPC duration during which a frame's DMA packet was
73-
// running on a video node (if mTrackGPUVideo==true)
74-
uint64_t ScreenTime; // QPC value when the present was displayed on screen
75-
72+
GPUVideoDuration; // QPC duration during which a frame's DMA packet was
73+
// running on a video node (if mTrackGPUVideo==true)
7674
uint64_t InputTime; // Earliest QPC value for all keyboard/mouse input used by this frame
7775
uint64_t MouseClickTime; // Earliest QPC value when the mouse was clicked and used by this frame
7876

@@ -81,6 +79,11 @@ struct PmNsmPresentEvent
8179
int32_t SyncInterval;
8280
uint32_t PresentFlags;
8381

82+
// (FrameType, DisplayedQPC) for each time the frame was displayed
83+
uint64_t Displayed_ScreenTime[16];
84+
FrameType Displayed_FrameType[16];
85+
uint32_t DisplayedCount;
86+
8487
// Keys used to index into PMTraceConsumer's tracking data structures:
8588
uint64_t CompositionSurfaceLuid; // mPresentByWin32KPresentHistoryToken
8689
uint64_t Win32KPresentCount; // mPresentByWin32KPresentHistoryToken

‎PresentMon/OutputThread.cpp‎

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -406,7 +406,6 @@ static void ReportMetricsHelper(
406406
chain->mLastReceivedNotDisplayedMouseClickTime = p->MouseClickTime;
407407
}
408408
}
409-
metrics.mClickToPhotonLatency = pmSession.TimestampDeltaToUnsignedMilliSeconds(p->InputTime, screenTime);
410409
} else {
411410
metrics.mClickToPhotonLatency = 0;
412411
metrics.mAllInputPhotonLatency = 0;

0 commit comments

Comments
 (0)