Skip to content

Commit

Permalink
Clean up error logging in scheduler code
Browse files Browse the repository at this point in the history
  • Loading branch information
@Psychlist1972
Psychlist1972 committed Apr 17, 2024
1 parent 5f70948 commit 4d78d7f
Show file tree
Hide file tree
Showing 2 changed files with 108 additions and 38 deletions.
2 changes: 1 addition & 1 deletion build/staging/version/BundleInfo.wxi
View file
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
<Include>
<?define SetupVersionName="Developer Preview 6 arm64" ?>
<?define SetupVersionNumber="1.0.24107.1653" ?>
<?define SetupVersionNumber="1.0.24107.2219" ?>
</Include>
144 changes: 107 additions & 37 deletions src/api/Transform/SchedulerTransform/Midi2.SchedulerMidiTransform.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -129,9 +129,14 @@ CMidi2SchedulerMidiTransform::Cleanup()
}
catch (...)
{
OutputDebugString(L"" __FUNCTION__ " Exception cleaning up");
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Exception cleaning up", "message")
);

// TODO: Log
return S_OK; // we don't care when cleaning up
}
}
Expand All @@ -150,20 +155,31 @@ CMidi2SchedulerMidiTransform::SendMidiMessageNow(
{
if (m_callback != nullptr)
{
m_callback->Callback(data, size, timestamp, m_context);
return S_OK;
return m_callback->Callback(data, size, timestamp, m_context);
}
else
{
OutputDebugString(L"" __FUNCTION__ " Failure: Callback is nullptr.");
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Callback is nullptr", "message")
);

// TODO: Log this
return E_FAIL;
}
}
catch (...)
{
// TODO: Log
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Exception sending MIDI Message", "message")
);

return E_FAIL;
}

Expand All @@ -176,8 +192,6 @@ HRESULT
CMidi2SchedulerMidiTransform::SendMidiMessageNow(
ScheduledUmpMessage const message)
{
// OutputDebugString((std::wstring(L"" __FUNCTION__ " Sending queued message. Queue size is: ") + std::to_wstring(m_messageQueue.size())).c_str());

if (!m_continueProcessing) return S_OK;

return SendMidiMessageNow(
Expand All @@ -197,12 +211,11 @@ CMidi2SchedulerMidiTransform::SendMidiMessage(
UINT size,
LONGLONG timestamp)
{

if (!m_continueProcessing) return S_OK;

try
{
// check to see if we're bypassing scheduling
// check to see if we're bypassing scheduling by sending a zero timestamp
if (timestamp == 0)
{
// bypass scheduling logic completely
Expand All @@ -214,6 +227,15 @@ CMidi2SchedulerMidiTransform::SendMidiMessage(
}
else
{
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingHResult(hr, "hresult"),
TraceLoggingWideString(L"Error sending MIDI Message now (bypass queue)", "message")
);

return hr;
}
}
Expand All @@ -228,15 +250,20 @@ CMidi2SchedulerMidiTransform::SendMidiMessage(
}
else
{
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingHResult(hr, "hresult"),
TraceLoggingWideString(L"Error sending MIDI Message now (message timestamp older than window)", "message")
);

return hr;
}
}
else
{
//// bypass scheduling for a stable release
//auto hr = SendMidiMessageNow(data, size, timestamp);
//return hr;

// otherwise, we schedule the message

if (size >= MINIMUM_UMP_DATASIZE && size <= MAXIMUM_UMP_DATASIZE)
Expand Down Expand Up @@ -266,21 +293,42 @@ CMidi2SchedulerMidiTransform::SendMidiMessage(
// priority queue doesn't give us any way to pop from the back
// so we just have to fail.

TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Outbound message queue full", "message")
);

return HR_E_MIDI_SENDMSG_SCHEDULER_QUEUE_FULL;
}
}
else
{
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Invalid message data size", "message")
);

// invalid data size
return HR_E_MIDI_SENDMSG_INVALID_MESSAGE;
}
}

// return S_OK;
}
catch (...)
{
// TODO: Log
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Exception scheduling message", "message")
);

return E_FAIL;
}

Expand All @@ -306,8 +354,6 @@ CMidi2SchedulerMidiTransform::GetTopMessageTimestamp(internal::MidiTimestamp &ti
{
timestamp = m_messageQueue.top().Timestamp;
ret = S_OK;

// OutputDebugString(L"\n--Retrieved current timestamp\n");
}
else
{
Expand All @@ -316,6 +362,14 @@ CMidi2SchedulerMidiTransform::GetTopMessageTimestamp(internal::MidiTimestamp &ti
}
catch (...)
{
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Exception getting top-message timestamp", "message")
);

ret = E_FAIL;
}

Expand All @@ -325,7 +379,10 @@ CMidi2SchedulerMidiTransform::GetTopMessageTimestamp(internal::MidiTimestamp &ti

_Use_decl_annotations_
HRESULT
CMidi2SchedulerMidiTransform::CalculateSafeSleepTime(internal::MidiTimestamp nextWakeupWindowTimestamp, uint32_t & sleepMS)
CMidi2SchedulerMidiTransform::CalculateSafeSleepTime(
internal::MidiTimestamp nextWakeupWindowTimestamp,
uint32_t& sleepMS
)
{
if (!m_continueProcessing) return E_FAIL;

Expand All @@ -338,8 +395,10 @@ CMidi2SchedulerMidiTransform::CalculateSafeSleepTime(internal::MidiTimestamp nex

if (nextWakeupWindowTimestamp > now)
{
// calculate diff in seconds
auto diff = (nextWakeupWindowTimestamp - now) / m_timestampFrequency;

// convert to milliseconds
sleepMS = (uint32_t)(diff * 1000);

// if the sleep time is under the limit, we don't sleep at all because the timing is not that accurate
Expand All @@ -353,6 +412,14 @@ CMidi2SchedulerMidiTransform::CalculateSafeSleepTime(internal::MidiTimestamp nex
}
catch (...)
{
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Exception calculating safe sleep time", "message")
);

ret = E_FAIL;
}

Expand All @@ -363,8 +430,6 @@ CMidi2SchedulerMidiTransform::CalculateSafeSleepTime(internal::MidiTimestamp nex

void CMidi2SchedulerMidiTransform::QueueWorker()
{
OutputDebugString(L"" __FUNCTION__ " Enter");

try
{
const uint64_t totalExpectedLatency = m_deviceLatencyTicks + MIDI_SCHEDULER_LOCK_AND_SEND_FUNCTION_LATENCY_TICKS;
Expand All @@ -375,13 +440,10 @@ void CMidi2SchedulerMidiTransform::QueueWorker()
// to wake up due to a new message arriving or due to shut down.
if (m_continueProcessing && m_messageQueue.empty())
{
OutputDebugString(L"" __FUNCTION__ " queue is empty. About to sleep");

// queue empty so sleep until we get notified to wake up
bool triggered = m_messageProcessorWakeup.wait(MIDI_OUTBOUND_EMPTY_QUEUE_SLEEP_DURATION_MS);

if (triggered) OutputDebugString(L"" __FUNCTION__ " Wake up from sleep");

m_messageProcessorWakeup.wait(MIDI_OUTBOUND_EMPTY_QUEUE_SLEEP_DURATION_MS);
//bool triggered = m_messageProcessorWakeup.wait(MIDI_OUTBOUND_EMPTY_QUEUE_SLEEP_DURATION_MS);
//if (triggered) OutputDebugString(L"" __FUNCTION__ " Wake up from sleep");
}
else if (m_continueProcessing && !m_messageQueue.empty())
{
Expand Down Expand Up @@ -420,9 +482,16 @@ void CMidi2SchedulerMidiTransform::QueueWorker()
{
LOG_IF_FAILED(hr);

TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingHResult(hr, "hresult")
);

// we failed to send for some reason, so break out of the loop. We'll catch
// these messages the next time around.
OutputDebugString(L"" __FUNCTION__ " Failed to send MIDI message");
break;
}

Expand All @@ -447,7 +516,7 @@ void CMidi2SchedulerMidiTransform::QueueWorker()
else
{
// couldn't get top timestamp for some reason.
OutputDebugString(L"" __FUNCTION__ " Unable to get top timestamp");
//OutputDebugString(L"" __FUNCTION__ " Unable to get top timestamp");
}

}
Expand All @@ -468,13 +537,14 @@ void CMidi2SchedulerMidiTransform::QueueWorker()
}
catch (...)
{
// TODO: Log
OutputDebugString(L"" __FUNCTION__ " Exception");
TraceLoggingWrite(
MidiSchedulerTransformTelemetryProvider::Provider(),
__FUNCTION__,
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingPointer(this, "this"),
TraceLoggingWideString(L"Exception processing queue", "message")
);
}


OutputDebugString((std::wstring(L"" __FUNCTION__ " Exit. Abandoned queue size is: ") + std::to_wstring(m_messageQueue.size())).c_str());

}


0 comments on commit 4d78d7f

Please sign in to comment.