Bug 1470333: Part 1 - Optimize debug logging statements in FormAutoFillContent. r?MattN draft
authorKris Maglione <maglione.k@gmail.com>
Sat, 30 Jun 2018 15:55:18 -0700
changeset 812909 f7bb68c8e866e393b97e6672a30b4beddc448997
parent 812908 09dba2361768a9d79a6fc4e65f93eda29c96373a
child 812910 e67160db3c8a9ff5fe0b7ea96ad11c42238c6fac
push id114701
push usermaglione.k@gmail.com
push dateSat, 30 Jun 2018 23:09:19 +0000
reviewersMattN
bugs1470333
milestone63.0a1
Bug 1470333: Part 1 - Optimize debug logging statements in FormAutoFillContent. r?MattN These cause us to load Console.jsm and create a ConsoleAPI instance in every content process, which is expensive both in terms of memory and startup performance. Checking the log level before we touch the console object is much cheaper, in terms of both memory and performance. MozReview-Commit-ID: 19f0ggAda2J
browser/extensions/formautofill/FormAutofillContent.jsm
browser/extensions/formautofill/FormAutofillUtils.jsm
--- a/browser/extensions/formautofill/FormAutofillContent.jsm
+++ b/browser/extensions/formautofill/FormAutofillContent.jsm
@@ -93,17 +93,17 @@ AutofillProfileAutoCompleteSearch.protot
    * @param {string} searchParam
    * @param {Object} previousResult a previous result to use for faster searchinig
    * @param {Object} listener the listener to notify when the search is complete
    */
   startSearch(searchString, searchParam, previousResult, listener) {
     let {activeInput, activeSection, activeFieldDetail, savedFieldNames} = FormAutofillContent;
     this.forceStop = false;
 
-    this.log.debug("startSearch: for", searchString, "with input", activeInput);
+    this.debug("startSearch: for", searchString, "with input", activeInput);
 
     let isAddressField = FormAutofillUtils.isAddressField(activeFieldDetail.fieldName);
     let isInputAutofilled = activeFieldDetail.state == FIELD_STATES.AUTO_FILLED;
     let allFieldNames = activeSection.allFieldNames;
     let filledRecordGUID = activeSection.filledRecordGUID;
     let searchPermitted = isAddressField ?
                           FormAutofillUtils.isAutofillAddressesEnabled :
                           FormAutofillUtils.isAutofillCreditCardsEnabled;
@@ -191,17 +191,17 @@ AutofillProfileAutoCompleteSearch.protot
    * @param  {string} data.searchString
    *         The typed string for filtering out the matched records.
    * @param  {string} data.info
    *         The input autocomplete property's information.
    * @returns {Promise}
    *          Promise that resolves when addresses returned from parent process.
    */
   _getRecords(data) {
-    this.log.debug("_getRecords with data:", data);
+    this.debug("_getRecords with data:", data);
     return new Promise((resolve) => {
       Services.cpmm.addMessageListener("FormAutofill:Records", function getResult(result) {
         Services.cpmm.removeMessageListener("FormAutofill:Records", getResult);
         resolve(result.data);
       });
 
       Services.cpmm.sendAsyncMessage("FormAutofill:GetRecords", data);
     });
@@ -217,30 +217,30 @@ let ProfileAutocomplete = {
   _factory: null,
 
   ensureRegistered() {
     if (this._registered) {
       return;
     }
 
     FormAutofillUtils.defineLazyLogGetter(this, "ProfileAutocomplete");
-    this.log.debug("ensureRegistered");
+    this.debug("ensureRegistered");
     this._factory = new AutocompleteFactory();
     this._factory.register(AutofillProfileAutoCompleteSearch);
     this._registered = true;
 
     Services.obs.addObserver(this, "autocomplete-will-enter-text");
   },
 
   ensureUnregistered() {
     if (!this._registered) {
       return;
     }
 
-    this.log.debug("ensureUnregistered");
+    this.debug("ensureUnregistered");
     this._factory.unregister();
     this._factory = null;
     this._registered = false;
     this._lastAutoCompleteResult = null;
 
     Services.obs.removeObserver(this, "autocomplete-will-enter-text");
   },
 
@@ -270,17 +270,17 @@ let ProfileAutocomplete = {
     if (selectedIndexResult.length != 1 || !Number.isInteger(selectedIndexResult[0])) {
       throw new Error("Invalid autocomplete selectedIndex");
     }
 
     return selectedIndexResult[0];
   },
 
   _fillFromAutocompleteRow(focusedInput) {
-    this.log.debug("_fillFromAutocompleteRow:", focusedInput);
+    this.debug("_fillFromAutocompleteRow:", focusedInput);
     let formDetails = FormAutofillContent.activeFormDetails;
     if (!formDetails) {
       // The observer notification is for a different frame.
       return;
     }
 
     let selectedIndex = this._getSelectedIndex(focusedInput.ownerGlobal);
     if (selectedIndex == -1 ||
@@ -383,31 +383,31 @@ var FormAutofillContent = {
    * 3. Number of filled fields is less than autofill threshold
    *
    * @param {HTMLElement} formElement Root element which receives earlyformsubmit event.
    * @param {Object} domWin Content window
    * @returns {boolean} Should always return true so form submission isn't canceled.
    */
   notify(formElement, domWin) {
     try {
-      this.log.debug("Notifying form early submission");
+      this.debug("Notifying form early submission");
 
       if (!FormAutofillUtils.isAutofillEnabled) {
-        this.log.debug("Form Autofill is disabled");
+        this.debug("Form Autofill is disabled");
         return true;
       }
 
       if (domWin && PrivateBrowsingUtils.isContentWindowPrivate(domWin)) {
-        this.log.debug("Ignoring submission in a private window");
+        this.debug("Ignoring submission in a private window");
         return true;
       }
 
       let handler = this._formsDetails.get(formElement);
       if (!handler) {
-        this.log.debug("Form element could not map to an existing handler");
+        this.debug("Form element could not map to an existing handler");
         return true;
       }
 
       let records = handler.createRecords();
       if (!Object.values(records).some(typeRecords => typeRecords.length)) {
         return true;
       }
 
@@ -525,36 +525,36 @@ var FormAutofillContent = {
           break;
         }
       }
     }
     return this._activeItems.fieldDetail;
   },
 
   identifyAutofillFields(element) {
-    this.log.debug("identifyAutofillFields:", "" + element.ownerDocument.location);
+    this.debug("identifyAutofillFields:", element.ownerDocument.location.href);
 
     if (!this.savedFieldNames) {
-      this.log.debug("identifyAutofillFields: savedFieldNames are not known yet");
+      this.debug("identifyAutofillFields: savedFieldNames are not known yet");
       Services.cpmm.sendAsyncMessage("FormAutofill:InitStorage");
     }
 
     let formHandler = this._getFormHandler(element);
     if (!formHandler) {
       let formLike = FormLikeFactory.createFromField(element);
       formHandler = new FormAutofillHandler(formLike);
     } else if (!formHandler.updateFormIfNeeded(element)) {
-      this.log.debug("No control is removed or inserted since last collection.");
+      this.debug("No control is removed or inserted since last collection.");
       return;
     }
 
     let validDetails = formHandler.collectFormFields();
 
     this._formsDetails.set(formHandler.form.rootElement, formHandler);
-    this.log.debug("Adding form handler to _formsDetails:", formHandler);
+    this.debug("Adding form handler to _formsDetails:", formHandler);
 
     validDetails.forEach(detail =>
       this._markAsAutofillField(detail.elementWeakRef.get())
     );
   },
 
   clearForm() {
     let focusedInput = this.activeInput || ProfileAutocomplete._lastAutoCompleteFocusedInput;
--- a/browser/extensions/formautofill/FormAutofillUtils.jsm
+++ b/browser/extensions/formautofill/FormAutofillUtils.jsm
@@ -40,16 +40,36 @@ const SECTION_TYPES = {
 // attacks that fill the user's hard drive(s).
 const MAX_FIELD_VALUE_LENGTH = 200;
 
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 ChromeUtils.import("resource://gre/modules/Services.jsm");
 ChromeUtils.defineModuleGetter(this, "CreditCard",
   "resource://gre/modules/CreditCard.jsm");
 
+XPCOMUtils.defineLazyPreferenceGetter(this, "logLevel", "extensions.formautofill.loglevel",
+                                      "error");
+
+// A logging helper for debug logging to avoid creating Console objects
+// or triggering expensive JS -> C++ calls when debug logging is not
+// enabled.
+//
+// Console objects, even natively-implemented ones, can consume a lot of
+// memory, and since this code may run in every content process, that
+// memory can add up quickly. And, even when debug-level messages are
+// being ignored, console.debug() calls can be expensive.
+//
+// This helper avoids both of those problems by never touching the
+// console object unless debug logging is enabled.
+function debug() {
+  if (logLevel == "debug") {
+    this.log.debug(...arguments);
+  }
+}
+
 let AddressDataLoader = {
   // Status of address data loading. We'll load all the countries with basic level 1
   // information while requesting conutry information, and set country to true.
   // Level 1 Set is for recording which country's level 1/level 2 data is loaded,
   // since we only load this when getCountryAddressData called with level 1 parameter.
   _dataLoaded: {
     country: false,
     level1: new Set(),
@@ -333,16 +353,18 @@ this.FormAutofillUtils = {
     for (let field in address) {
       if (field != "tel" && this.getCategoryFromFieldName(field) == "tel") {
         delete address[field];
       }
     }
   },
 
   defineLazyLogGetter(scope, logPrefix) {
+    scope.debug = debug;
+
     XPCOMUtils.defineLazyGetter(scope, "log", () => {
       let ConsoleAPI = ChromeUtils.import("resource://gre/modules/Console.jsm", {}).ConsoleAPI;
       return new ConsoleAPI({
         maxLogLevelPref: "extensions.formautofill.loglevel",
         prefix: logPrefix,
       });
     });
   },