Process info logging

Starting in Runtime V33, logging is available for processes, windows, views, and memory usage. Specifically, the following will be logged:

Process logging
Window and view creation logging
Window and view tear-down logging
Memory usage outliers logging

This functionality will only be available when the logging mode is set to verbose.

Process logging

Periodic process logging logs all process information for each PID in the OpenFin system. The information is similar to the information returned by the fin.System.getAllProcessInfo function.

The default logging interval is 30 seconds. This interval can be controlled using the following runtime argument which specifies the interval in seconds:

--process-logging-interval=15

There will be one log entry per PID, and the log entries follow the following format:

[3352:0323/105834.142461:VERBOSE1:electron_api_app.cc(1853)] Process Info: {"pid":3411,"cpuUsage":0,"nonPagedPoolUsage":0,"pageFaultCount":0,"pagedPoolUsage":0,"pagefileUsage":0,"peakNonPagedPoolUsage":0,"peakPagedPoolUsage":0,"peakPagefileUsage":0,"peakWorkingSetSize":0,"workingSetSize":0,"privateSetSize":0,"entities":[],"iframes":[{"url":"https://a125375509.cdn.optimizely.com/client_storage/a125375509.html","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}}]}

[3352:0323/105834.143019:VERBOSE1:electron_api_app.cc(1853)] Process Info: {"pid":3410,"cpuUsage":0,"nonPagedPoolUsage":0,"pageFaultCount":0,"pagedPoolUsage":0,"pagefileUsage":0,"peakNonPagedPoolUsage":0,"peakPagedPoolUsage":0,"peakPagefileUsage":0,"peakWorkingSetSize":0,"workingSetSize":0,"privateSetSize":0,"entities":[{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}],"iframes":[{"url":"about:blank","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}},{"url":"about:blank","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}},{"url":"about:blank","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}},{"url":"about:blank","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}},{"url":"about:srcdoc","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}},{"url":"about:blank","entityType":"iframe","parent":{"uuid":"example_platform","name":"abc","url":"https://www.cnn.com/","entityType":"window"}}]}

[3352:0323/105834.143043:VERBOSE1:electron_api_app.cc(1853)] Process Info: {"pid":"3352","name":"Browser","cpuUsage":2.12,"nonPagedPoolUsage":0,"pageFaultCount":0,"pagedPoolUsage":0,"pagefileUsage":348581888,"peakNonPagedPoolUsage":0,"peakPagedPoolUsage":0,"peakPagefileUsage":0,"peakWorkingSetSize":0,"workingSetSize":114708480,"privateSetSize":21532672}

Window and view creation logging

When a window or view are created, we log the PID used by the renderer, the entity type, and all options except customData, customContext, and Interop state as those entries may contain sensitive information.

The window and view creation log entries follow the following format:

{
  "name": "view-b61b5aff-20a2-460e-a56f-26639b26928e",
  "uuid": "openfin-app",
  "entityType": "view",
  "url": "https://example.com",
  "pid": 3456,
  "alwaysOnTop": false,
  "frame": true,
  "icon": "",
  "maxHeight": -1,
  "maxWidth": -1,
  "maximizable": true,
  "minHeight": 0,
  "minWidth": 0,
  "minimizable": true,
  "opacity": 1,
  "resizeRegion": {
    "bottomRightCorner": 9,
    "size": 7,
    "sides": {
      "top": true,
      "right": true,
      "bottom": true,
      "left": true
      }
  },
  "transparent": false,
  "webPreferences": {
    "api": {
      "batching": {
        "renderer": {
          "enabled": false,
          "maxSize": 1.7976931348623157e+308,
          "ttl": 0
        }
      },
      "breadcrumbs": false,
      "iframe": {
        "crossOriginInjection": false,
        "sameOriginInjection": true,
        "enableDeprecatedSharedName": false
      }
    },
    "contextMenuSettings": {
      "enable": true,
      "devtools": true,
      "reload": true
    },
    "disableInitialReload": false,
    "nodeIntegration": false,
    "plugins": false,
    "sandbox": true,
    "spellcheck": false,
    "backgroundThrottling": false,
    "useElectronWillPreventUnload": false,
    "electronContextMenu": true,
    "autoplayPolicy": "no-user-gesture-required"
  },
  "accelerator": {
    "devtools": false,
    "zoom": false,
    "reload": false,
    "reloadIgnoringCache": false
  },
  "alphaMask": {
    "blue": -1,
    "green": -1,
    "red": -1
  },
  "alwaysOnBottom": false,
  "api": {
    "iframe": {
      "crossOriginInjection": false,
      "sameOriginInjection": true,
      "enableDeprecatedSharedName": false
    }
  },
  "applicationIcon": "",
  "aspectRatio": 0,
  "autoShow": true,
  "backgroundThrottling": false,
  "contentNavigation": {
    "whitelist": [
      "<all_urls>"
    ],
    "blacklist": []
  },
  "contentRedirect": {
    "whitelist": [
      "<all_urls>"
    ],
    "blacklist": []
  },
  "contextMenuSettings": {
    "enable": true,
    "devtools": true,
    "reload": true
  },
  "cornerRounding": {
    "height": 0,
    "width": 0
  },
  "closeOnLastViewRemoved": true,
  "defaultCentered": false,
  "defaultHeight": 500,
  "defaultLeft": 10,
  "defaultTop": 10,
  "defaultWidth": 800,
  "disableIabSecureLogging": false,
  "draggable": false,
  "exitOnClose": false,
  "experimental": {
    "api": {
      "batching": {
        "renderer": {
          "enabled": false,
          "maxSize": 1.7976931348623157e+308,
          "ttl": 0
        }
      },
      "breadcrumbs": false,
        "iframe": {
          "crossOriginInjection": false,
          "sameOriginInjection": true,
          "enableDeprecatedSharedName": false
        }
      },
      "v2Api": true,
      "useChromiumContextMenu": false
  },
  "hideOnBlur": false,
  "hideOnClose": false,
  "hideWhileChildrenVisible": false,
  "isRawWindowOpen": false,
  "includeInSnapshots": true,
  "launchExternal": "",
  "loadErrorMessage": "",
  "plugins": false,
  "resizable": true,
  "resize": true,
  "saveWindowState": false,
  "shadow": false,
  "showTaskbarIcon": true,
  "smallWindow": false,
  "spellCheck": false,
  "state": "normal",
  "taskbarIcon": "",
  "taskbarIconGroup": "app-1679412989488-8462",
  "waitForPageLoad": true,
  "backgroundColor": "#FFF",
  "webSecurity": true,
  "fdc3InteropApi": "",
  "enableBeforeUnload": false,
  "hotkeys": [],
  "autoplayPolicy": "no-user-gesture-required",
  "show": false,
  "skipTaskbar": false,
  "title": "app-1679412989488-8462",
  "height": 1036,
  "width": 636,
  "center": false,
  "x": 642,
  "y": 20,
  "enableLargerThanScreen": true,
  "enable-plugins": true,
  "ignoreSavedWindowState": true,
  "hasLoaded": false
}

Window and view tear-down logging

When a Window or View is destroyed, we log the last known process information for these entities. This is the same information returned by Window.getProcessInfo and View.getProcessInfo:

 {
  "name": "view-b61b5aff-20a2-460e-a56f-26639b26928e",
  "uuid": "openfin-app",
  "entityType": "view",
  "url": "https://example.com",
  "cpuUsage": 0.03,
  "nonPagedPoolUsage": 21368,
  "pageFaultCount": 37313,
  "pagedPoolUsage": 623720,
  "pagefileUsage": 29847552,
  "peakNonPagedPoolUsage": 23568,
  "peakPagedPoolUsage": 631912,
  "peakPagefileUsage": 40046592,
  "peakWorkingSetSize": 81715200,
  "workingSetSize": 76034048,
  "privateSetSize": 29847552,
  "pid": 22724,
  "iframes": []
}

The process information taken right before shutdown can reveal issues related to resource usage.

Memory usage outliers logging

Every 5 seconds, we store the current process information in a buffer, both in memory and in a file. When the buffer stores a sufficient amount of data (144 entries, which is 12 minutes from the application start), we log every future entry where PID memory usage is an outlier.

The buffer write interval and the number of entries to store before detecting outliers can be controlled through these two runtime arguments:

--process-logging-outlier-interval=10
--process-logging-outlier-entries=200

We use a simple statistical model for detecting outliers that assumes the least about the data, the 1.5 IQR rule. According to the 1.5 IQR rule, outliers are any points that are greater than 1.5*IQR*Q3 or less than 1.5*IQR*Q1. Q1 is the median of the lower half of the sorted data, Q3, is the median of the upper half of the sorted data, and IQR stands for Inter Quartile Range(Q3-Q1) and describes the middle 50% of the data, sorted in ascending order.

The information logged is similar to the information returned by the fin.System.getAllProcessInfo function, and looks similar to the following:

{
  "pid": 1234,
  "workingSetSize": 76034048,
  "privateSetSize": 29847552,
  "entities": [
    {
      "name": "view-b61b5aff-20a2-460e-a56f-26639b26928e",
      "uuid": "openfin-app",
      "entityType": "view",
      "url": "https://example.com",
    },
    {
      "name": "internal-generated-window-3dad69c5-067a-4c75-8670-02b0ece76fdf",
      "uuid": "openfin-app",
      "entityType": "window",
      "url": "https://openfin.co",
    }
  ]
}

The buffer will be stored in a file called processInfoBuffer.json inside the Runtime cache folder. This file is retained in case of an application crash.

This logging data allows you to access the most recent process info which will help you know when your app has inconsistent memory usage.

APIs for process logging

The Process Logging options detailed above can be controlled through an API:

fin.System.updateProcessLoggingOptions({
  interval: 10,
  outlierDetection: {
    entries: 200,
    interval: 10
  }
});

type ProcessLogginOptions {
  interval: number;
  outlierDetection: {
    entries: number;
    interval: number;
  }
}