How logging can leak memory in JavaScript

Everyone of us is using some kind of logging in our applications. I actually didn't thought that logging can be evil to me...

Recently I recognized that my lovely Aurelia app was getting slower and slower and that it struggled with big data tables in some cases. Once I got some time and analyzed the problem and found quite fast some things to improve. The Performance tab in Chrome gave me nice insights about load times, memory consumption and performance of single functions and their call stack. After some navigation through my Aurelia application I found a quite interesting memory leak. There were actually quite many places where I sadly kept references to some view models and custom elements which lead to a huge dom tree and other objects not being garbage collected. Luckily all of those were easy to fix by adjusting my self written annotations and subscription management to use the bind and unbind lifecycle of the view models and custom elements. After I ensured that all references are cleaned up properly I were super happy and confident I'm done and I did another check. I opened a the affected page, took a heap snapshot, navigated to another page and back again. Then I took another heap snapshot and compared those and were badly suprised that the DOM tree was still not cleaned up by the garbage collector :(. I traced down all the node references to find the root reference but I couldn't. As the dom tree were to huge to traverse it manually I saved the heap snapshot and wrote a small script using the npm module 'heapsnapshot' to traverse the nodes programmatically and find the nasty reference.

Finally!!! I again didn't found the reference -,-

I was super annoyed and started the next day an exclusion process by removing step by step parts from my application and checked every time if the memory leak is resolved. After 3 days and a lot of disapointing results I finally found the issue.

The problem

In my Aurelia application I want to have scss rules which are scoped to the page they should apply on. To do this I add the name of the current route to the router-view by listening for route changes.

Code: app.js

import {LogManager} from 'aurelia-framework';
import {RouterConfiguration, Router} from 'aurelia-router';
import {EventAggregator} from 'aurelia-event-aggregator';
import {AuthorizationStep} from 'app/feature/auth/index';
import {routes} from 'app/routes';
const log = LogManager.getLogger('app/app');
export class App {
static inject = [EventAggregator];
/**
* @param {EventAggregator} ea
*/
constructor(ea: EventAggregator) {
this.currentRoute = null;
// Listen for route changes to update the route name
ea.subscribe('router:navigation:complete', ({instruction}) => {
log.debug('Main route switched', instruction);
this.currentRoute = instruction.router.currentInstruction && instruction.router.currentInstruction.config.name;
});
}
/**
* @param {RouterConfiguration} config
*/
configureRouter(config: RouterConfiguration): void {
config.map(routes);
}
}

Alles anzeigen

Code: app.html

<template>
<router-view class="pl-xl pr-xl pb-xxxl row page ${currentRoute}"></router-view>
</template>

Do you already see the memory leak? Maybe you got it from the title of this post but maybe you are that helpless like me^^ The problem here is the logging line log.debug('Main route switched', instruction); which actually logs the instruction object. In chrome the log will be saved to the memory even when your dev tools are not enabled so that you can see it if you open it. In this case and also if you would just use console.log, the actual log message is not serialized but instead the reference to the object is logged and you're able to analyze it in the dev tools. So here is our nasty reference. The instruction which holds the container with the viewModel were referenced by the dev tools and I were to blind to see it because the reference is not shown the same way like other references

The learning

After that shiny moment I learned that we should not just log everything in debug mode to be able to understand problems better. Even if you have to log objects you should serialize them using JSON.stringify instead of logging the object itself. A simple log method which serializes it's parameters can solve that already.

const log => (...args) => console.log(args.map(arg => typeof arg === 'object' ? JSON.stringify(arg) : arg).join(' '))

I hope my insights could help you a bit and you'll pay some attention to evil logging and nasty references

The problem

The learning

Teilen