overleaf/libraries/metrics/event_loop.coffee

module.exports = EventLoopMonitor =
	monitor: (logger, interval = 1000, log_threshold = 100) ->
		Metrics = require "./metrics"
		# check for logger on startup to avoid exceptions later if undefined
		throw new Error("logger is undefined") if !logger?
		# monitor delay in setInterval to detect event loop blocking
		previous = Date.now()
		intervalId = setInterval () ->
			now = Date.now()
			offset = now - previous - interval
			if offset > log_threshold
				logger.warn {offset: offset}, "slow event loop"
			previous = now
			Metrics.timing("event-loop-millsec", offset)
		, interval
		
		Metrics.registerDestructor () ->
			clearInterval(intervalId)
added monitoring of event loop time should indicate if node is blocking on libuv threads as described in https://nodejs.org/api/dns.html#dns_dns_lookup 2015-06-23 05:51:48 -04:00			`module.exports = EventLoopMonitor =`
Monitor event loop by looking for skew If we monitor with setImmediate, we miss big blocking loops. For example, suppose we have 1000 1ms loops then a single bad 1000ms loop. setImmediate will only be called at the right time 1/1000 of the time (it has to be the loop just before the bad one). So this monitoring method gives a good average if the std dev is low, but doesn't pick up spikes. Instead, we can monitor the skew from the expected time between setIntervals. In the case above, with a setInterval for 1000ms, we will pick up a skew proportional to the amount of time that it overlaps the bad loop. So 50% change of picking up skew > 500ms, and thus getting a good sense of any spikes. 2015-12-03 11:32:20 -05:00			`monitor: (logger, interval = 1000, log_threshold = 100) ->`
added monitoring of event loop time should indicate if node is blocking on libuv threads as described in https://nodejs.org/api/dns.html#dns_dns_lookup 2015-06-23 05:51:48 -04:00			`Metrics = require "./metrics"`
handle undefined logger in event loop monitor 2018-05-10 05:10:34 -04:00			`# check for logger on startup to avoid exceptions later if undefined`
			`throw new Error("logger is undefined") if !logger?`
			`# monitor delay in setInterval to detect event loop blocking`
Monitor event loop by looking for skew If we monitor with setImmediate, we miss big blocking loops. For example, suppose we have 1000 1ms loops then a single bad 1000ms loop. setImmediate will only be called at the right time 1/1000 of the time (it has to be the loop just before the bad one). So this monitoring method gives a good average if the std dev is low, but doesn't pick up spikes. Instead, we can monitor the skew from the expected time between setIntervals. In the case above, with a setInterval for 1000ms, we will pick up a skew proportional to the amount of time that it overlaps the bad loop. So 50% change of picking up skew > 500ms, and thus getting a good sense of any spikes. 2015-12-03 11:32:20 -05:00			`previous = Date.now()`
			`intervalId = setInterval () ->`
			`now = Date.now()`
			`offset = now - previous - interval`
			`if offset > log_threshold`
			`logger.warn {offset: offset}, "slow event loop"`
			`previous = now`
			`Metrics.timing("event-loop-millsec", offset)`
			`, interval`

added monitoring of event loop time should indicate if node is blocking on libuv threads as described in https://nodejs.org/api/dns.html#dns_dns_lookup 2015-06-23 05:51:48 -04:00			`Metrics.registerDestructor () ->`
Monitor event loop by looking for skew If we monitor with setImmediate, we miss big blocking loops. For example, suppose we have 1000 1ms loops then a single bad 1000ms loop. setImmediate will only be called at the right time 1/1000 of the time (it has to be the loop just before the bad one). So this monitoring method gives a good average if the std dev is low, but doesn't pick up spikes. Instead, we can monitor the skew from the expected time between setIntervals. In the case above, with a setInterval for 1000ms, we will pick up a skew proportional to the amount of time that it overlaps the bad loop. So 50% change of picking up skew > 500ms, and thus getting a good sense of any spikes. 2015-12-03 11:32:20 -05:00			`clearInterval(intervalId)`