0
# Profiling
1

2
Built-in profiling utilities for measuring operation performance and logging execution times.
3

4
## Capabilities
5

6
### Profiler Class
7

8
Class for measuring execution time of operations and logging performance metrics.
9

10
```javascript { .api }
11
/**
12
 * Profiler for measuring operation execution time
13
 */
14
class Profiler {
15
  constructor(logger: Logger);
16
  
17
  /** Associated logger instance */
18
  logger: Logger;
19
  /** Start timestamp in milliseconds */
20
  start: number;
21
}
22
```
23

24
### Profiler Methods
25

26
Methods for completing profiling measurements and logging results.
27

28
```javascript { .api }
29
/**
30
 * Complete the profiling measurement and log the duration
31
 * @param args - Optional arguments, last one can be info object
32
 * @returns Boolean indicating success
33
 */
34
done(...args: any[]): boolean;
35
```
36

37
**Usage Examples:**
38

39
```javascript
40
const winston = require('winston');
41

42
const logger = winston.createLogger({
43
  transports: [new winston.transports.Console()]
44
});
45

46
// Manual profiler creation
47
const profiler = new winston.Profiler(logger);
48

49
// Simulate some work
50
setTimeout(() => {
51
  profiler.done('Database query completed');
52
  // Logs: { level: 'info', message: 'Database query completed', durationMs: 1002 }
53
}, 1000);
54

55
// With custom info object
56
const profiler2 = new winston.Profiler(logger);
57
setTimeout(() => {
58
  profiler2.done({
59
    message: 'API request processed',
60
    level: 'debug',
61
    operation: 'getUserData',
62
    userId: 123
63
  });
64
  // Logs with durationMs added to the info object
65
}, 500);
66
```
67

68
### Logger Profiling Methods
69

70
Built-in profiling methods available on Logger instances for convenient performance measurement.
71

72
```javascript { .api }
73
/**
74
 * Start a timer and return a Profiler instance
75
 * @returns Profiler instance for measuring duration
76
 */
77
startTimer(): Profiler;
78

79
/**
80
 * Profile an operation by ID, logging start and completion
81
 * @param id - Unique identifier for the operation
82
 * @param meta - Optional metadata for the profile log
83
 * @returns Logger instance for chaining
84
 */
85
profile(id: string | number, meta?: Record<string, any>): Logger;
86
```
87

88
**Usage Examples:**
89

90
```javascript
91
const winston = require('winston');
92

93
const logger = winston.createLogger({
94
  transports: [new winston.transports.Console()]
95
});
96

97
// Using startTimer
98
const timer = logger.startTimer();
99
// ... perform some operation
100
timer.done('Operation completed');
101

102
// Using profile method
103
logger.profile('database-query');
104
// ... perform database query
105
logger.profile('database-query'); // Logs the duration
106

107
// Profile with metadata
108
logger.profile('api-request', { endpoint: '/users', method: 'GET' });
109
// ... process API request
110
logger.profile('api-request', { endpoint: '/users', method: 'GET' });
111
```
112

113
### Global Profiling Methods
114

115
Profiling methods available on the winston module using the default logger.
116

117
```javascript { .api }
118
/**
119
 * Start a timer using the default logger
120
 * @returns Profiler instance
121
 */
122
function startTimer(): Profiler;
123

124
/**
125
 * Profile an operation using the default logger
126
 * @param id - Unique identifier for the operation
127
 * @param meta - Optional metadata
128
 * @returns Default logger instance
129
 */
130
function profile(id: string | number, meta?: Record<string, any>): Logger;
131
```
132

133
**Usage Examples:**
134

135
```javascript
136
const winston = require('winston');
137

138
// Configure default logger
139
winston.add(new winston.transports.Console());
140

141
// Global profiling
142
const timer = winston.startTimer();
143
// ... perform operation
144
timer.done('Global operation completed');
145

146
// Global profile method
147
winston.profile('global-task');
148
// ... perform task
149
winston.profile('global-task');
150
```
151

152
### Advanced Profiling Patterns
153

154
**Multiple concurrent profiles:**
155

156
```javascript
157
const winston = require('winston');
158

159
const logger = winston.createLogger({
160
  format: winston.format.combine(
161
    winston.format.timestamp(),
162
    winston.format.json()
163
  ),
164
  transports: [new winston.transports.Console()]
165
});
166

167
class PerformanceTracker {
168
  constructor(logger) {
169
    this.logger = logger;
170
    this.activeProfiles = new Map();
171
  }
172

173
  start(operationId, metadata = {}) {
174
    const timer = this.logger.startTimer();
175
    this.activeProfiles.set(operationId, {
176
      timer,
177
      metadata,
178
      startTime: Date.now()
179
    });
180
    
181
    this.logger.info('Operation started', {
182
      operationId,
183
      ...metadata
184
    });
185
  }
186

187
  end(operationId, additionalData = {}) {
188
    const profile = this.activeProfiles.get(operationId);
189
    if (profile) {
190
      profile.timer.done({
191
        message: 'Operation completed',
192
        operationId,
193
        ...profile.metadata,
194
        ...additionalData
195
      });
196
      
197
      this.activeProfiles.delete(operationId);
198
    }
199
  }
200

201
  checkpoint(operationId, checkpointName) {
202
    const profile = this.activeProfiles.get(operationId);
203
    if (profile) {
204
      const elapsed = Date.now() - profile.startTime;
205
      this.logger.info('Operation checkpoint', {
206
        operationId,
207
        checkpoint: checkpointName,
208
        elapsedMs: elapsed,
209
        ...profile.metadata
210
      });
211
    }
212
  }
213
}
214

215
// Usage
216
const tracker = new PerformanceTracker(logger);
217

218
tracker.start('user-registration', { userId: 123 });
219
// ... validate input
220
tracker.checkpoint('user-registration', 'validation-complete');
221
// ... save to database  
222
tracker.checkpoint('user-registration', 'database-save-complete');
223
// ... send email
224
tracker.end('user-registration', { emailSent: true });
225
```
226

227
**HTTP request profiling middleware:**
228

229
```javascript
230
const winston = require('winston');
231

232
const logger = winston.createLogger({
233
  format: winston.format.combine(
234
    winston.format.timestamp(),
235
    winston.format.json()
236
  ),
237
  transports: [
238
    new winston.transports.Console(),
239
    new winston.transports.File({ filename: 'performance.log' })
240
  ]
241
});
242

243
// Express middleware for request profiling
244
const profileRequests = (req, res, next) => {
245
  const requestId = req.headers['x-request-id'] || Date.now().toString();
246
  const timer = logger.startTimer();
247
  
248
  req.requestId = requestId;
249
  req.startTime = Date.now();
250
  
251
  logger.info('Request started', {
252
    requestId,
253
    method: req.method,
254
    url: req.url,
255
    userAgent: req.headers['user-agent'],
256
    ip: req.ip
257
  });
258

259
  // Override res.end to capture response time
260
  const originalEnd = res.end;
261
  res.end = function(...args) {
262
    timer.done({
263
      message: 'Request completed',
264
      requestId,
265
      method: req.method,
266
      url: req.url,
267
      statusCode: res.statusCode,
268
      contentLength: res.get('content-length') || 0
269
    });
270
    
271
    originalEnd.apply(this, args);
272
  };
273

274
  next();
275
};
276

277
module.exports = profileRequests;
278
```
279

280
**Database query profiling:**
281

282
```javascript
283
const winston = require('winston');
284

285
const logger = winston.createLogger({
286
  transports: [new winston.transports.Console()]
287
});
288

289
class DatabaseProfiler {
290
  constructor(logger) {
291
    this.logger = logger;
292
  }
293

294
  async profileQuery(queryName, queryFn, queryParams = {}) {
295
    const timer = this.logger.startTimer();
296
    const startTime = Date.now();
297
    
298
    this.logger.debug('Database query started', {
299
      query: queryName,
300
      params: queryParams
301
    });
302

303
    try {
304
      const result = await queryFn();
305
      
306
      timer.done({
307
        message: 'Database query completed',
308
        query: queryName,
309
        params: queryParams,
310
        resultCount: Array.isArray(result) ? result.length : 1,
311
        level: 'debug'
312
      });
313
      
314
      return result;
315
    } catch (error) {
316
      const elapsed = Date.now() - startTime;
317
      
318
      this.logger.error('Database query failed', {
319
        query: queryName,
320
        params: queryParams,
321
        error: error.message,
322
        durationMs: elapsed
323
      });
324
      
325
      throw error;
326
    }
327
  }
328
}
329

330
// Usage
331
const dbProfiler = new DatabaseProfiler(logger);
332

333
async function getUserById(userId) {
334
  return await dbProfiler.profileQuery(
335
    'getUserById',
336
    () => database.users.findById(userId),
337
    { userId }
338
  );
339
}
340

341
async function getOrdersByUser(userId, limit = 10) {
342
  return await dbProfiler.profileQuery(
343
    'getOrdersByUser',
344
    () => database.orders.findByUserId(userId, limit),
345
    { userId, limit }
346
  );
347
}
348
```
349

350
**Performance monitoring with thresholds:**
351

352
```javascript
353
const winston = require('winston');
354

355
const logger = winston.createLogger({
356
  format: winston.format.combine(
357
    winston.format.timestamp(),
358
    winston.format.json()
359
  ),
360
  transports: [
361
    new winston.transports.Console(),
362
    new winston.transports.File({ filename: 'performance.log' })
363
  ]
364
});
365

366
class PerformanceMonitor {
367
  constructor(logger, thresholds = {}) {
368
    this.logger = logger;
369
    this.thresholds = {
370
      warn: 1000,  // 1 second
371
      error: 5000, // 5 seconds
372
      ...thresholds
373
    };
374
  }
375

376
  profile(operationName, operation, metadata = {}) {
377
    return new Promise((resolve, reject) => {
378
      const timer = this.logger.startTimer();
379
      const startTime = Date.now();
380

381
      Promise.resolve(operation())
382
        .then(result => {
383
          const duration = Date.now() - startTime;
384
          const level = this.getLogLevel(duration);
385
          
386
          timer.done({
387
            message: `Operation ${operationName} completed`,
388
            operation: operationName,
389
            level,
390
            ...metadata,
391
            performanceFlag: duration > this.thresholds.warn ? 'SLOW' : 'NORMAL'
392
          });
393

394
          resolve(result);
395
        })
396
        .catch(error => {
397
          const duration = Date.now() - startTime;
398
          
399
          this.logger.error(`Operation ${operationName} failed`, {
400
            operation: operationName,
401
            error: error.message,
402
            durationMs: duration,
403
            ...metadata
404
          });
405

406
          reject(error);
407
        });
408
    });
409
  }
410

411
  getLogLevel(duration) {
412
    if (duration >= this.thresholds.error) return 'error';
413
    if (duration >= this.thresholds.warn) return 'warn';
414
    return 'info';
415
  }
416
}
417

418
// Usage
419
const monitor = new PerformanceMonitor(logger, {
420
  warn: 500,  // 500ms
421
  error: 2000 // 2 seconds
422
});
423

424
// Monitor async operations
425
monitor.profile('file-processing', async () => {
426
  const data = await fs.readFile('large-file.txt');
427
  return processData(data);
428
}, { fileSize: '10MB' });
429

430
// Monitor API calls
431
monitor.profile('external-api-call', () => {
432
  return fetch('https://api.example.com/data');
433
}, { endpoint: '/data' });
434
```