send shutdown event when dll is unloaded and EvaluationStop, SessionC… (#2704)

* send shutdown event when dll is unloaded and EvaluationStop, SessionCreationStart Events.

* Add EvalutationStart Event

* add comment
This commit is contained in:
Xiang Zhang 2019-12-20 16:11:21 -08:00 committed by GitHub
parent db9b72df43
commit a3750c102f
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
9 changed files with 78 additions and 3 deletions

View file

@ -23,6 +23,15 @@ void Telemetry::DisableTelemetryEvents() const {
void Telemetry::LogProcessInfo() const {
}
void Telemetry::LogSessionCreationStart() const {
}
void Telemetry::LogEvaluationStop() const {
}
void Telemetry::LogEvaluationStart() const {
}
void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, const std::string& model_producer_name,
const std::string& model_producer_version, const std::string& model_domain,
const std::unordered_map<std::string, int>& domain_to_version_map,

View file

@ -38,6 +38,12 @@ class Telemetry {
virtual void LogProcessInfo() const;
virtual void LogSessionCreationStart() const;
virtual void LogEvaluationStop() const;
virtual void LogEvaluationStart() const;
virtual void LogSessionCreation(uint32_t session_id, int64_t ir_version, const std::string& model_producer_name,
const std::string& model_producer_version, const std::string& model_domain,
const std::unordered_map<std::string, int>& domain_to_version_map,

View file

@ -87,6 +87,30 @@ void WindowsTelemetry::LogProcessInfo() const {
process_info_logged = true;
}
void WindowsTelemetry::LogSessionCreationStart() const {
TraceLoggingWrite(telemetry_provider_handle,
"SessionCreationStart",
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES));
}
void WindowsTelemetry::LogEvaluationStop() const {
TraceLoggingWrite(telemetry_provider_handle,
"EvaluationStop",
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES));
}
void WindowsTelemetry::LogEvaluationStart() const {
TraceLoggingWrite(telemetry_provider_handle,
"EvaluationStart",
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES));
}
void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, const std::string& model_producer_name,
const std::string& model_producer_version, const std::string& model_domain,
const std::unordered_map<std::string, int>& domain_to_version_map,

View file

@ -23,6 +23,12 @@ class WindowsTelemetry : public Telemetry {
void LogProcessInfo() const override;
void LogSessionCreationStart() const override;
void LogEvaluationStop() const override;
void LogEvaluationStart() const override;
void LogSessionCreation(uint32_t session_id, int64_t ir_version, const std::string& model_producer_name,
const std::string& model_producer_version, const std::string& model_domain,
const std::unordered_map<std::string, int>& domain_to_version_map,

View file

@ -791,6 +791,8 @@ common::Status InferenceSession::Initialize() {
try {
LOGS(*session_logger_, INFO) << "Initializing session.";
std::lock_guard<onnxruntime::OrtMutex> l(session_mutex_);
const Env& env = Env::Default();
env.GetTelemetryProvider().LogSessionCreationStart();
if (!is_model_loaded_) {
LOGS(*session_logger_, ERROR) << "Model was not loaded";
return common::Status(common::ONNXRUNTIME, common::FAIL, "Model was not loaded.");
@ -870,7 +872,6 @@ common::Status InferenceSession::Initialize() {
is_inited_ = true;
// and log telemetry
const Env& env = Env::Default();
bool model_use_fp16 = ModelUseFP16(model_->ToProto());
env.GetTelemetryProvider().LogSessionCreation(session_id_, model_->IrVersion(), model_->ProducerName(), model_->ProducerVersion(),
model_->Domain(), model_->MainGraph().DomainToVersionMap(), model_->MainGraph().Name(),
@ -1053,13 +1054,21 @@ Status InferenceSession::Run(const RunOptions& run_options, const std::vector<st
TraceLoggingWriteStart(ortrun_activity, "OrtRun");
#endif
Status retval = Status::OK();
const Env& env = Env::Default();
try {
if (!is_inited_) {
LOGS(*session_logger_, ERROR) << "Session was not initialized";
return Status(common::ONNXRUNTIME, common::FAIL, "Session not initialized.");
}
// check the frequency to send Evalutaion Stop event
if (TimeDiffMicroSeconds(time_sent_last_evalutation_start_) > kDurationBetweenSendingEvaluationStart) {
env.GetTelemetryProvider().LogEvaluationStart();
// reset counters
time_sent_last_evalutation_start_ = std::chrono::high_resolution_clock::now();
isEvaluationStart = true;
}
ORT_RETURN_IF_ERROR_SESSIONID_(ValidateInputs(feed_names, feeds));
ORT_RETURN_IF_ERROR_SESSIONID_(ValidateOutputs(output_names, p_fetches));
@ -1111,7 +1120,6 @@ Status InferenceSession::Run(const RunOptions& run_options, const std::vector<st
// time to send telemetry?
if (TimeDiffMicroSeconds(time_sent_last_) > kDurationBetweenSending) {
// send the telemetry
const Env& env = Env::Default();
env.GetTelemetryProvider().LogRuntimePerf(session_id_, total_runs_since_last_, total_run_duration_since_last_);
// reset counters
time_sent_last_ = std::chrono::high_resolution_clock::now();
@ -1119,6 +1127,11 @@ Status InferenceSession::Run(const RunOptions& run_options, const std::vector<st
total_run_duration_since_last_ = 0;
}
// check the frequency to send Evalutaion Stop event
if (isEvaluationStart) {
env.GetTelemetryProvider().LogEvaluationStop();
isEvaluationStart = false;
}
// send out profiling events (optional)
if (session_profiler_.IsEnabled()) {
session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_run", tp);

View file

@ -510,6 +510,11 @@ class InferenceSession {
const long long kDurationBetweenSending = 1000 * 1000 * 60 * 10; // duration in (us). send a report every 10 mins
std::string event_name_; // where the model is loaded from: ["model_loading_uri", "model_loading_proto", "model_loading_istream"]
TimePoint time_sent_last_evalutation_start_;
// Event Rate per provider < 20 peak events per second
const long long kDurationBetweenSendingEvaluationStart = 1000 * 50; // duration in (us). send a EvaluationStop Event every 50 ms;
bool isEvaluationStart = false;
#ifdef ONNXRUNTIME_ENABLE_INSTRUMENT
bool session_activity_started_ = false;
TraceLoggingActivity<telemetry_provider_handle> session_activity;

View file

@ -33,6 +33,7 @@ extern "C" BOOL WINAPI DllMain(_In_ HINSTANCE hInstance, DWORD dwReason, _In_ vo
wil::SetResultTelemetryFallback(&OnErrorReported);
break;
case DLL_PROCESS_DETACH:
telemetry_helper.LogWinMLShutDown();
// Unregister Trace Logging Provider feeding telemetry
telemetry_helper.UnRegister();

View file

@ -79,6 +79,8 @@ class WinMLTelemetryHelper {
void UnRegister() {
TraceLoggingUnregister(provider_);
}
void LogWinMLShutDown();
void LogRuntimeError(HRESULT hr, std::string message, PCSTR file, PCSTR function, int line);
void LogRuntimeError(HRESULT hr, PCSTR message, PCSTR file, PCSTR function, int line);
void LogRegisterOperatorKernel(

View file

@ -16,6 +16,15 @@ WinMLTelemetryHelper::WinMLTelemetryHelper()
WinMLTelemetryHelper::~WinMLTelemetryHelper() {
}
void WinMLTelemetryHelper::LogWinMLShutDown() {
WinMLTraceLoggingWrite(
provider_,
"WinMLShutDown",
TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance),
TraceLoggingString("windows.ai.machinelearning.dll is unloaded", "message"),
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES));
}
void WinMLTelemetryHelper::LogRuntimeError(HRESULT hr, PCSTR message, PCSTR file, PCSTR function, int line) {
if (!telemetry_enabled_)