onnxruntime

1
// Copyright (c) Microsoft Corporation. All rights reserved.
2
// Licensed under the MIT License.
3

4
import { Env } from 'onnxruntime-common';
5

6
import { WebGLContext } from './backends/webgl/webgl-context';
7

8
export declare namespace Logger {
9
  export interface SeverityTypeMap {
10
    verbose: 'v';
11
    info: 'i';
12
    warning: 'w';
13
    error: 'e';
14
    fatal: 'f';
15
  }
16

17
  export type Severity = keyof SeverityTypeMap;
18

19
  export type Provider = 'none' | 'console';
20

21
  /**
22
   * Logging config that used to control the behavior of logger
23
   */
24
  export interface Config {
25
    /**
26
     * Specify the logging provider. 'console' by default
27
     */
28
    provider?: Provider;
29
    /**
30
     * Specify the minimal logger serverity. 'warning' by default
31
     */
32
    minimalSeverity?: Logger.Severity;
33
    /**
34
     * Whether to output date time in log. true by default
35
     */
36
    logDateTime?: boolean;
37
    /**
38
     * Whether to output source information (Not yet supported). false by default
39
     */
40
    logSourceLocation?: boolean;
41
  }
42

43
  export interface CategorizedLogger {
44
    verbose(content: string): void;
45
    info(content: string): void;
46
    warning(content: string): void;
47
    error(content: string): void;
48
    fatal(content: string): void;
49
  }
50
}
51

52
// eslint-disable-next-line @typescript-eslint/no-redeclare
53
export interface Logger {
54
  (category: string): Logger.CategorizedLogger;
55

56
  verbose(content: string): void;
57
  verbose(category: string, content: string): void;
58
  info(content: string): void;
59
  info(category: string, content: string): void;
60
  warning(content: string): void;
61
  warning(category: string, content: string): void;
62
  error(content: string): void;
63
  error(category: string, content: string): void;
64
  fatal(content: string): void;
65
  fatal(category: string, content: string): void;
66

67
  /**
68
   * Reset the logger configuration.
69
   * @param config specify an optional default config
70
   */
71
  reset(config?: Logger.Config): void;
72
  /**
73
   * Set the logger's behavior on the given category
74
   * @param category specify a category string. If '*' is specified, all previous configuration will be overwritten. If
75
   * '' is specified, the default behavior will be updated.
76
   * @param config the config object to indicate the logger's behavior
77
   */
78
  set(category: string, config: Logger.Config): void;
79

80
  /**
81
   * Set the logger's behavior from ort-common env
82
   * @param env the env used to set logger. Currently only setting loglevel is supported through Env.
83
   */
84
  setWithEnv(env: Env): void;
85
}
86

87
interface LoggerProvider {
88
  log(severity: Logger.Severity, content: string, category?: string): void;
89
}
90
class NoOpLoggerProvider implements LoggerProvider {
91
  log(_severity: Logger.Severity, _content: string, _category?: string) {
92
    // do nothing
93
  }
94
}
95
class ConsoleLoggerProvider implements LoggerProvider {
96
  log(severity: Logger.Severity, content: string, category?: string) {
97
    // eslint-disable-next-line no-console
98
    console.log(`${this.color(severity)} ${category ? '\x1b[35m' + category + '\x1b[0m ' : ''}${content}`);
99
  }
100

101
  private color(severity: Logger.Severity) {
102
    switch (severity) {
103
      case 'verbose':
104
        return '\x1b[34;40mv\x1b[0m';
105
      case 'info':
106
        return '\x1b[32mi\x1b[0m';
107
      case 'warning':
108
        return '\x1b[30;43mw\x1b[0m';
109
      case 'error':
110
        return '\x1b[31;40me\x1b[0m';
111
      case 'fatal':
112
        return '\x1b[101mf\x1b[0m';
113
      default:
114
        throw new Error(`unsupported severity: ${severity}`);
115
    }
116
  }
117
}
118

119
const SEVERITY_VALUE = {
120
  verbose: 1000,
121
  info: 2000,
122
  warning: 4000,
123
  error: 5000,
124
  fatal: 6000,
125
};
126

127
const LOGGER_PROVIDER_MAP: { readonly [provider: string]: Readonly<LoggerProvider> } = {
128
  ['none']: new NoOpLoggerProvider(),
129
  ['console']: new ConsoleLoggerProvider(),
130
};
131
const LOGGER_DEFAULT_CONFIG = {
132
  provider: 'console',
133
  minimalSeverity: 'warning',
134
  logDateTime: true,
135
  logSourceLocation: false,
136
};
137
let LOGGER_CONFIG_MAP: { [category: string]: Readonly<Required<Logger.Config>> } = {
138
  ['']: LOGGER_DEFAULT_CONFIG as Required<Logger.Config>,
139
};
140

141
function log(category: string): Logger.CategorizedLogger;
142
function log(severity: Logger.Severity, content: string): void;
143
function log(severity: Logger.Severity, category: string, content: string): void;
144
function log(severity: Logger.Severity, arg1: string, arg2?: string): void;
145
function log(
146
  arg0: string | Logger.Severity,
147
  arg1?: string,
148
  arg2?: string | number,
149
  arg3?: number,
150
): Logger.CategorizedLogger | void {
151
  if (arg1 === undefined) {
152
    // log(category: string): Logger.CategorizedLogger;
153
    return createCategorizedLogger(arg0);
154
  } else if (arg2 === undefined) {
155
    // log(severity, content);
156
    logInternal(arg0 as Logger.Severity, arg1, 1);
157
  } else if (typeof arg2 === 'number' && arg3 === undefined) {
158
    // log(severity, content, stack)
159
    logInternal(arg0 as Logger.Severity, arg1, arg2);
160
  } else if (typeof arg2 === 'string' && arg3 === undefined) {
161
    // log(severity, category, content)
162
    logInternal(arg0 as Logger.Severity, arg2, 1, arg1);
163
  } else if (typeof arg2 === 'string' && typeof arg3 === 'number') {
164
    // log(severity, category, content, stack)
165
    logInternal(arg0 as Logger.Severity, arg2, arg3, arg1);
166
  } else {
167
    throw new TypeError('input is valid');
168
  }
169
}
170

171
function createCategorizedLogger(category: string): Logger.CategorizedLogger {
172
  return {
173
    verbose: log.verbose.bind(null, category),
174
    info: log.info.bind(null, category),
175
    warning: log.warning.bind(null, category),
176
    error: log.error.bind(null, category),
177
    fatal: log.fatal.bind(null, category),
178
  };
179
}
180

181
// NOTE: argument 'category' is put the last parameter beacause typescript
182
// doesn't allow optional argument put in front of required argument. This
183
// order is different from a usual logging API.
184
function logInternal(severity: Logger.Severity, content: string, _stack: number, category?: string) {
185
  const config = LOGGER_CONFIG_MAP[category || ''] || LOGGER_CONFIG_MAP[''];
186
  if (SEVERITY_VALUE[severity] < SEVERITY_VALUE[config.minimalSeverity]) {
187
    return;
188
  }
189

190
  if (config.logDateTime) {
191
    content = `${new Date().toISOString()}|${content}`;
192
  }
193

194
  if (config.logSourceLocation) {
195
    // TODO: calculate source location from 'stack'
196
  }
197

198
  LOGGER_PROVIDER_MAP[config.provider].log(severity, content, category);
199
}
200

201
// eslint-disable-next-line @typescript-eslint/no-namespace
202
namespace log {
203
  export function verbose(content: string): void;
204
  export function verbose(category: string, content: string): void;
205
  export function verbose(arg0: string, arg1?: string) {
206
    log('verbose', arg0, arg1);
207
  }
208
  export function info(content: string): void;
209
  export function info(category: string, content: string): void;
210
  export function info(arg0: string, arg1?: string) {
211
    log('info', arg0, arg1);
212
  }
213
  export function warning(content: string): void;
214
  export function warning(category: string, content: string): void;
215
  export function warning(arg0: string, arg1?: string) {
216
    log('warning', arg0, arg1);
217
  }
218
  export function error(content: string): void;
219
  export function error(category: string, content: string): void;
220
  export function error(arg0: string, arg1?: string) {
221
    log('error', arg0, arg1);
222
  }
223
  export function fatal(content: string): void;
224
  export function fatal(category: string, content: string): void;
225
  export function fatal(arg0: string, arg1?: string) {
226
    log('fatal', arg0, arg1);
227
  }
228

229
  export function reset(config?: Logger.Config): void {
230
    LOGGER_CONFIG_MAP = {};
231
    set('', config || {});
232
  }
233
  export function set(category: string, config: Logger.Config): void {
234
    if (category === '*') {
235
      reset(config);
236
    } else {
237
      const previousConfig = LOGGER_CONFIG_MAP[category] || LOGGER_DEFAULT_CONFIG;
238
      LOGGER_CONFIG_MAP[category] = {
239
        provider: config.provider || previousConfig.provider,
240
        minimalSeverity: config.minimalSeverity || previousConfig.minimalSeverity,
241
        logDateTime: config.logDateTime === undefined ? previousConfig.logDateTime : config.logDateTime,
242
        logSourceLocation:
243
          config.logSourceLocation === undefined ? previousConfig.logSourceLocation : config.logSourceLocation,
244
      };
245
    }
246

247
    // TODO: we want to support wildcard or regex?
248
  }
249

250
  export function setWithEnv(env: Env): void {
251
    const config: Logger.Config = {};
252
    if (env.logLevel) {
253
      config.minimalSeverity = env.logLevel as Logger.Severity;
254
    }
255
    set('', config);
256
  }
257
}
258

259
// eslint-disable-next-line @typescript-eslint/no-redeclare, @typescript-eslint/naming-convention
260
export const Logger: Logger = log;
261

262
export declare namespace Profiler {
263
  export interface Config {
264
    maxNumberEvents?: number;
265
    flushBatchSize?: number;
266
    flushIntervalInMilliseconds?: number;
267
  }
268

269
  export type EventCategory = 'session' | 'node' | 'op' | 'backend';
270

271
  export interface Event {
272
    end(): void | Promise<void>;
273
  }
274
}
275
// TODO
276
// class WebGLEvent implements Profiler.Event {}
277

278
class Event implements Profiler.Event {
279
  constructor(
280
    public category: Profiler.EventCategory,
281
    public name: string,
282
    public startTime: number,
283
    private endCallback: (e: Event) => void | Promise<void>,
284
    public timer?: WebGLQuery,
285
    public ctx?: WebGLContext,
286
  ) {}
287

288
  async end() {
289
    return this.endCallback(this);
290
  }
291

292
  async checkTimer(): Promise<number> {
293
    if (this.ctx === undefined || this.timer === undefined) {
294
      throw new Error('No webgl timer found');
295
    } else {
296
      this.ctx.endTimer();
297
      return this.ctx.waitForQueryAndGetTime(this.timer);
298
    }
299
  }
300
}
301

302
class EventRecord {
303
  constructor(
304
    public category: Profiler.EventCategory,
305
    public name: string,
306
    public startTime: number,
307
    public endTime: number,
308
  ) {}
309
}
310

311
export class Profiler {
312
  static create(config?: Profiler.Config): Profiler {
313
    if (config === undefined) {
314
      return new this();
315
    }
316
    return new this(config.maxNumberEvents, config.flushBatchSize, config.flushIntervalInMilliseconds);
317
  }
318

319
  private constructor(maxNumberEvents?: number, flushBatchSize?: number, flushIntervalInMilliseconds?: number) {
320
    this._started = false;
321
    this._maxNumberEvents = maxNumberEvents === undefined ? 10000 : maxNumberEvents;
322
    this._flushBatchSize = flushBatchSize === undefined ? 10 : flushBatchSize;
323
    this._flushIntervalInMilliseconds = flushIntervalInMilliseconds === undefined ? 5000 : flushIntervalInMilliseconds;
324
  }
325

326
  // start profiling
327
  start() {
328
    this._started = true;
329
    this._timingEvents = [];
330
    this._flushTime = now();
331
    this._flushPointer = 0;
332
  }
333

334
  // stop profiling
335
  stop() {
336
    this._started = false;
337
    for (; this._flushPointer < this._timingEvents.length; this._flushPointer++) {
338
      this.logOneEvent(this._timingEvents[this._flushPointer]);
339
    }
340
  }
341

342
  // create an event scope for the specific function
343
  event<T>(category: Profiler.EventCategory, name: string, func: () => T, ctx?: WebGLContext): T;
344
  event<T>(category: Profiler.EventCategory, name: string, func: () => Promise<T>, ctx?: WebGLContext): Promise<T>;
345

346
  event<T>(
347
    category: Profiler.EventCategory,
348
    name: string,
349
    func: () => T | Promise<T>,
350
    ctx?: WebGLContext,
351
  ): T | Promise<T> {
352
    const event = this._started ? this.begin(category, name, ctx) : undefined;
353
    let isPromise = false;
354

355
    const res = func();
356

357
    // we consider a then-able object is a promise
358
    if (res && typeof (res as Promise<T>).then === 'function') {
359
      isPromise = true;
360
      return new Promise<T>((resolve, reject) => {
361
        (res as Promise<T>).then(
362
          async (value) => {
363
            // fulfilled
364
            if (event) {
365
              await event.end();
366
            }
367
            resolve(value);
368
          },
369
          async (reason) => {
370
            // rejected
371
            if (event) {
372
              await event.end();
373
            }
374
            reject(reason);
375
          },
376
        );
377
      });
378
    }
379
    if (!isPromise && event) {
380
      const eventRes = event.end();
381
      if (eventRes && typeof eventRes.then === 'function') {
382
        return new Promise<T>((resolve, reject) => {
383
          eventRes.then(
384
            () => {
385
              // fulfilled
386
              resolve(res);
387
            },
388
            (reason) => {
389
              // rejected
390
              reject(reason);
391
            },
392
          );
393
        });
394
      }
395
    }
396
    return res;
397
  }
398

399
  // begin an event
400
  begin(category: Profiler.EventCategory, name: string, ctx?: WebGLContext): Event {
401
    if (!this._started) {
402
      throw new Error('profiler is not started yet');
403
    }
404
    if (ctx === undefined) {
405
      const startTime = now();
406
      this.flush(startTime);
407
      return new Event(category, name, startTime, (e) => this.endSync(e));
408
    } else {
409
      const timer: WebGLQuery = ctx.beginTimer();
410
      return new Event(category, name, 0, async (e) => this.end(e), timer, ctx);
411
    }
412
  }
413

414
  // end the specific event
415
  private async end(event: Event): Promise<void> {
416
    const endTime: number = await event.checkTimer();
417
    if (this._timingEvents.length < this._maxNumberEvents) {
418
      this._timingEvents.push(new EventRecord(event.category, event.name, event.startTime, endTime));
419
      this.flush(endTime);
420
    }
421
  }
422

423
  private endSync(event: Event): void {
424
    const endTime: number = now();
425
    if (this._timingEvents.length < this._maxNumberEvents) {
426
      this._timingEvents.push(new EventRecord(event.category, event.name, event.startTime, endTime));
427
      this.flush(endTime);
428
    }
429
  }
430

431
  private logOneEvent(event: EventRecord) {
432
    Logger.verbose(
433
      `Profiler.${event.category}`,
434
      `${(event.endTime - event.startTime).toFixed(2)}ms on event '${event.name}' at ${event.endTime.toFixed(2)}`,
435
    );
436
  }
437

438
  private flush(currentTime: number) {
439
    if (
440
      this._timingEvents.length - this._flushPointer >= this._flushBatchSize ||
441
      currentTime - this._flushTime >= this._flushIntervalInMilliseconds
442
    ) {
443
      // should flush when either batch size accumlated or interval elepsed
444

445
      for (
446
        const previousPointer = this._flushPointer;
447
        this._flushPointer < previousPointer + this._flushBatchSize && this._flushPointer < this._timingEvents.length;
448
        this._flushPointer++
449
      ) {
450
        this.logOneEvent(this._timingEvents[this._flushPointer]);
451
      }
452

453
      this._flushTime = now();
454
    }
455
  }
456

457
  get started() {
458
    return this._started;
459
  }
460
  private _started = false;
461
  private _timingEvents: EventRecord[];
462

463
  private readonly _maxNumberEvents: number;
464

465
  private readonly _flushBatchSize: number;
466
  private readonly _flushIntervalInMilliseconds: number;
467

468
  private _flushTime: number;
469
  private _flushPointer = 0;
470
}
471

472
/**
473
 * returns a number to represent the current timestamp in a resolution as high as possible.
474
 */
475
export const now = typeof performance !== 'undefined' && performance.now ? () => performance.now() : Date.now;
476