From 450524359e6696f86a63ad950b0dbeb1c5cf86bb Mon Sep 17 00:00:00 2001 From: Sunghoon <35605090+hanbitmyths@users.noreply.github.com> Date: Tue, 7 Sep 2021 17:18:08 -0700 Subject: [PATCH] [js/web] WebAssembly profiling (#8932) * add p50 in test * Preallocate WebAssembly worker threads to minimize worker creation time * WebAssembly profiling * merge master * merge with proxy changes * disable profiling tests from WebAssembly build * fix e2e test failure Co-authored-by: Yulong Wang --- js/web/lib/wasm/binding/ort-wasm.d.ts | 2 ++ js/web/lib/wasm/proxy-messages.ts | 8 ++++++- js/web/lib/wasm/proxy-worker/main.ts | 11 +++++++++- js/web/lib/wasm/proxy-wrapper.ts | 21 +++++++++++++++++++ js/web/lib/wasm/session-handler.ts | 4 ++-- js/web/lib/wasm/session-options.ts | 7 ++++--- js/web/lib/wasm/wasm-core-impl.ts | 19 +++++++++++++++++ js/web/test/test-runner.ts | 2 +- onnxruntime/core/common/profiler.cc | 4 ++++ onnxruntime/core/common/profiler.h | 9 ++++++++ .../test/framework/inference_session_test.cc | 3 +++ onnxruntime/wasm/api.cc | 19 +++++++++++++++-- onnxruntime/wasm/api.h | 10 ++++++++- 13 files changed, 108 insertions(+), 11 deletions(-) diff --git a/js/web/lib/wasm/binding/ort-wasm.d.ts b/js/web/lib/wasm/binding/ort-wasm.d.ts index 6cc15d36a6..b93fe0a8db 100644 --- a/js/web/lib/wasm/binding/ort-wasm.d.ts +++ b/js/web/lib/wasm/binding/ort-wasm.d.ts @@ -43,6 +43,8 @@ export interface OrtWasmModule extends EmscriptenModule { _OrtCreateRunOptions(logSeverityLevel: number, logVerbosityLevel: number, terminate: boolean, tag: number): number; _OrtAddRunConfigEntry(runOptionsHandle: number, configKey: number, configValue: number): number; _OrtReleaseRunOptions(runOptionsHandle: number): void; + + _OrtEndProfiling(sessionHandle: number): number; //#endregion //#region config diff --git a/js/web/lib/wasm/proxy-messages.ts b/js/web/lib/wasm/proxy-messages.ts index 6438d7f7ee..d8dcbd3664 100644 --- a/js/web/lib/wasm/proxy-messages.ts +++ b/js/web/lib/wasm/proxy-messages.ts @@ -47,4 +47,10 @@ interface MessageRun extends MessageError { out?: SerializableTensor[]; } -export type OrtWasmMessage = MessageInitWasm|MessageInitOrt|MessageCreateSession|MessageReleaseSession|MessageRun; +interface MesssageEndProfiling extends MessageError { + type: 'end-profiling'; + in ?: number; +} + +export type OrtWasmMessage = + MessageInitWasm|MessageInitOrt|MessageCreateSession|MessageReleaseSession|MessageRun|MesssageEndProfiling; diff --git a/js/web/lib/wasm/proxy-worker/main.ts b/js/web/lib/wasm/proxy-worker/main.ts index 1ea4ea8132..876b0572e1 100644 --- a/js/web/lib/wasm/proxy-worker/main.ts +++ b/js/web/lib/wasm/proxy-worker/main.ts @@ -4,7 +4,7 @@ /// import {OrtWasmMessage} from '../proxy-messages'; -import {createSession, extractTransferableBuffers, initOrt, releaseSession, run} from '../wasm-core-impl'; +import {createSession, endProfiling, extractTransferableBuffers, initOrt, releaseSession, run} from '../wasm-core-impl'; import {initializeWebAssembly} from '../wasm-factory'; self.onmessage = (ev: MessageEvent): void => { @@ -51,6 +51,15 @@ self.onmessage = (ev: MessageEvent): void => { postMessage({type: 'run', err} as OrtWasmMessage); } break; + case 'end-profiling': + try { + const handler = ev.data.in!; + endProfiling(handler); + postMessage({type: 'end-profiling'} as OrtWasmMessage); + } catch (err) { + postMessage({type: 'end-profiling', err} as OrtWasmMessage); + } + break; default: } }; diff --git a/js/web/lib/wasm/proxy-wrapper.ts b/js/web/lib/wasm/proxy-wrapper.ts index 1c8f18706b..12b5b9287a 100644 --- a/js/web/lib/wasm/proxy-wrapper.ts +++ b/js/web/lib/wasm/proxy-wrapper.ts @@ -20,6 +20,7 @@ let initOrtCallbacks: PromiseCallbacks; const createSessionCallbacks: Array> = []; const releaseSessionCallbacks: Array> = []; const runCallbacks: Array> = []; +const endProfilingCallbacks: Array> = []; const ensureWorker = (): void => { if (initializing || !initialized || aborted || !proxyWorker) { @@ -67,6 +68,13 @@ const onProxyWorkerMessage = (ev: MessageEvent): void => { runCallbacks.shift()![0](ev.data.out!); } break; + case 'end-profiling': + if (ev.data.err) { + endProfilingCallbacks.shift()![1](ev.data.err); + } else { + endProfilingCallbacks.shift()![0](); + } + break; default: } }; @@ -163,3 +171,16 @@ export const run = async( return core.run(sessionId, inputIndices, inputs, outputIndices, options); } }; + +export const endProfiling = async(sessionId: number): Promise => { + if (isProxy()) { + ensureWorker(); + return new Promise((resolve, reject) => { + endProfilingCallbacks.push([resolve, reject]); + const message: OrtWasmMessage = {type: 'end-profiling', in : sessionId}; + proxyWorker!.postMessage(message); + }); + } else { + core.endProfiling(sessionId); + } +}; diff --git a/js/web/lib/wasm/session-handler.ts b/js/web/lib/wasm/session-handler.ts index dc87e5708c..ede51e8a24 100644 --- a/js/web/lib/wasm/session-handler.ts +++ b/js/web/lib/wasm/session-handler.ts @@ -3,7 +3,7 @@ import {env, InferenceSession, SessionHandler, Tensor} from 'onnxruntime-common'; -import {createSession, initOrt, releaseSession, run} from './proxy-wrapper'; +import {createSession, endProfiling, initOrt, releaseSession, run} from './proxy-wrapper'; let ortInit: boolean; @@ -85,6 +85,6 @@ export class OnnxruntimeWebAssemblySessionHandler implements SessionHandler { } endProfiling(): void { - // TODO: implement profiling + void endProfiling(this.sessionId); } } diff --git a/js/web/lib/wasm/session-options.ts b/js/web/lib/wasm/session-options.ts index 560de879c7..5b32fd5636 100644 --- a/js/web/lib/wasm/session-options.ts +++ b/js/web/lib/wasm/session-options.ts @@ -93,12 +93,13 @@ export const setSessionOptions = (options?: InferenceSession.SessionOptions): [n throw new Error(`log verbosity level is not valid: ${options.logVerbosityLevel}`); } - // TODO: Support profiling - sessionOptions.enableProfiling = false; + if (options?.enableProfiling === undefined) { + sessionOptions.enableProfiling = false; + } sessionOptionsHandle = wasm._OrtCreateSessionOptions( graphOptimizationLevel, !!sessionOptions.enableCpuMemArena!, !!sessionOptions.enableMemPattern!, executionMode, - sessionOptions.enableProfiling, 0, logIdDataOffset, sessionOptions.logSeverityLevel!, + !!sessionOptions.enableProfiling!, 0, logIdDataOffset, sessionOptions.logSeverityLevel!, sessionOptions.logVerbosityLevel!); if (sessionOptionsHandle === 0) { throw new Error('Can\'t create session options'); diff --git a/js/web/lib/wasm/wasm-core-impl.ts b/js/web/lib/wasm/wasm-core-impl.ts index 0d15daf49c..2b5d6cc6a8 100644 --- a/js/web/lib/wasm/wasm-core-impl.ts +++ b/js/web/lib/wasm/wasm-core-impl.ts @@ -385,6 +385,25 @@ export const run = } }; +/** + * end profiling + */ +export const endProfiling = (sessionId: number): void => { + const wasm = getInstance(); + const session = activeSessions[sessionId]; + if (!session) { + throw new Error('invalid session id'); + } + const sessionHandle = session[0]; + + // profile file name is not used yet, but it must be freed. + const profileFileName = wasm._OrtEndProfiling(sessionHandle); + if (profileFileName === 0) { + throw new Error('Can\'t get an profile file name'); + } + wasm._OrtFree(profileFileName); +}; + export const extractTransferableBuffers = (tensors: readonly SerializableTensor[]): ArrayBufferLike[] => { const buffers: ArrayBufferLike[] = []; for (const tensor of tensors) { diff --git a/js/web/test/test-runner.ts b/js/web/test/test-runner.ts index d906b7a124..68571db37a 100644 --- a/js/web/test/test-runner.ts +++ b/js/web/test/test-runner.ts @@ -124,7 +124,7 @@ async function initializeSession( preloadModelData ? ` [preloaded(${preloadModelData.byteLength})]` : ''}`); const profilerConfig = profile ? {maxNumberEvents: 65536} : undefined; - const sessionConfig = {executionProviders: [backendHint], profiler: profilerConfig}; + const sessionConfig = {executionProviders: [backendHint], profiler: profilerConfig, enableProfiling: profile}; let session: ort.InferenceSession; try { diff --git a/onnxruntime/core/common/profiler.cc b/onnxruntime/core/common/profiler.cc index ee752a6a62..7017fd9f3c 100644 --- a/onnxruntime/core/common/profiler.cc +++ b/onnxruntime/core/common/profiler.cc @@ -48,7 +48,9 @@ void Profiler::StartProfiling(const logging::Logger* custom_logger) { template void Profiler::StartProfiling(const std::basic_string& file_name) { enabled_ = true; +#if !defined(__wasm__) profile_stream_.open(file_name, std::ios::out | std::ios::trunc); +#endif profile_stream_file_ = ToMBString(file_name); profiling_start_time_ = StartTime(); } @@ -129,7 +131,9 @@ std::string Profiler::EndProfiling() { } } profile_stream_ << "]\n"; +#if !defined(__wasm__) profile_stream_.close(); +#endif enabled_ = false; // will not collect profile after writing. return profile_stream_file_; } diff --git a/onnxruntime/core/common/profiler.h b/onnxruntime/core/common/profiler.h index 2ef1a8ac65..3718f7ad27 100644 --- a/onnxruntime/core/common/profiler.h +++ b/onnxruntime/core/common/profiler.h @@ -121,7 +121,16 @@ class Profiler { // Mutex controlling access to profiler data OrtMutex mutex_; bool enabled_{false}; +#if defined(__wasm__) + /* + * The simplest way to emit profiling data in WebAssembly is to print out to console, + * since browsers can't access to a file system directly. + * TODO: Consider MEMFS or IndexedDB instead of console. + */ + std::ostream& profile_stream_{std::cout}; +#else std::ofstream profile_stream_; +#endif std::string profile_stream_file_; const logging::Logger* session_logger_{nullptr}; const logging::Logger* custom_logger_{nullptr}; diff --git a/onnxruntime/test/framework/inference_session_test.cc b/onnxruntime/test/framework/inference_session_test.cc index 3b3cb822a1..3b3ef5ee03 100644 --- a/onnxruntime/test/framework/inference_session_test.cc +++ b/onnxruntime/test/framework/inference_session_test.cc @@ -605,6 +605,8 @@ TEST(InferenceSessionTests, CheckRunLogger) { #endif } +// WebAssembly will emit profiling data into console +#if !defined(__wasm__) TEST(InferenceSessionTests, CheckRunProfilerWithSessionOptions) { SessionOptions so; @@ -686,6 +688,7 @@ TEST(InferenceSessionTests, CheckRunProfilerWithStartProfile) { count++; } } +#endif // __wasm__ TEST(InferenceSessionTests, CheckRunProfilerStartTime) { // Test whether the InferenceSession can access the profiler's start time diff --git a/onnxruntime/wasm/api.cc b/onnxruntime/wasm/api.cc index 1cc8dd8088..01feb71a0c 100644 --- a/onnxruntime/wasm/api.cc +++ b/onnxruntime/wasm/api.cc @@ -64,8 +64,8 @@ OrtSessionOptions* OrtCreateSessionOptions(size_t graph_optimization_level, bool enable_cpu_mem_arena, bool enable_mem_pattern, size_t execution_mode, - bool /* enable_profiling */, - const char* /* profile_file_prefix */, + bool enable_profiling, + const char* /*profile_file_prefix*/, const char* log_id, size_t log_severity_level, size_t log_verbosity_level) { @@ -93,6 +93,11 @@ OrtSessionOptions* OrtCreateSessionOptions(size_t graph_optimization_level, RETURN_NULLPTR_IF_ERROR(SetSessionExecutionMode, session_options, static_cast(execution_mode)); // TODO: support profling + if (enable_profiling) { + RETURN_NULLPTR_IF_ERROR(EnableProfiling, session_options, ""); + } else { + RETURN_NULLPTR_IF_ERROR(DisableProfiling, session_options); + } if (log_id != nullptr) { RETURN_NULLPTR_IF_ERROR(SetSessionLogId, session_options, log_id); @@ -345,3 +350,13 @@ int OrtRun(OrtSession* session, OrtRunOptions* run_options) { return CHECK_STATUS(Run, session, run_options, input_names, inputs, input_count, output_names, output_count, outputs); } + +char* OrtEndProfiling(ort_session_handle_t session) { + OrtAllocator* allocator = nullptr; + RETURN_NULLPTR_IF_ERROR(GetAllocatorWithDefaultOptions, &allocator); + + char* file_name = nullptr; + return (CHECK_STATUS(SessionEndProfiling, session, allocator, &file_name) == ORT_OK) + ? file_name + : nullptr; +} \ No newline at end of file diff --git a/onnxruntime/wasm/api.h b/onnxruntime/wasm/api.h index 5ac8b1f9cf..2c6ca6b9eb 100644 --- a/onnxruntime/wasm/api.h +++ b/onnxruntime/wasm/api.h @@ -41,7 +41,7 @@ int EMSCRIPTEN_KEEPALIVE OrtInit(int num_threads, int logging_level); * @param enable_cpu_mem_arena enable or disable cpu memory arena * @param enable_mem_pattern enable or disable memory pattern * @param execution_mode sequential or parallel execution mode - * @param enable_profiling enable or disable profiling. it's a no-op and for a future use. + * @param enable_profiling enable or disable profiling. * @param profile_file_prefix file prefix for profiling data. it's a no-op and for a future use. * @param log_id logger id for session output * @param log_severity_level verbose, info, warning, error or fatal @@ -185,4 +185,12 @@ int EMSCRIPTEN_KEEPALIVE OrtRun(ort_session_handle_t session, size_t output_count, ort_tensor_handle_t* outputs, ort_run_options_handle_t run_options); + +/** + * end profiling. + * @param session handle of the specified session + * @returns a pointer to a buffer which contains C-style string of profile filename. + * Caller must release the C style string after use by calling OrtFree(). + */ +char* EMSCRIPTEN_KEEPALIVE OrtEndProfiling(ort_session_handle_t session); };