LogBox - Schedule logs to unblock rendering

Summary:
Currently if you land of a surface with a lot of logs, we're basically blocked until they stop. This diff schedules the log parsing in LogBox to free up the app to do other things.

Changelog: [Internal]

Reviewed By: motiz88

Differential Revision: D18203391

fbshipit-source-id: 35c5f03316a1106a3a48e7770d5bb59c62a3694f

Libraries/LogBox/Data/LogBoxData.js

@@ -13,6 +13,7 @@
 import LogBoxLog from './LogBoxLog';
 import parseLogBoxLog from './parseLogBoxLog';
 import type {LogLevel} from './LogBoxLog';
+import parseErrorStack from '../../Core/Devtools/parseErrorStack';
 
 export type LogBoxLogs = Set<LogBoxLog>;
 
@@ -54,32 +55,41 @@ function handleUpdate(): void {
 }
 
 export function add(level: LogLevel, args: $ReadOnlyArray<mixed>): void {
-  // This is carried over from the old YellowBox, but it is not clear why.
-  if (typeof args[0] === 'string' && args[0].startsWith('(ADVICE)')) {
-    return;
-  }
+  const errorForStackTrace = new Error();
 
-  const {category, message, stack, componentStack} = parseLogBoxLog(args);
+  // Parsing logs are expensive so we schedule this
+  // otherwise spammy logs would pause rendering.
+  setImmediate(() => {
+    // This is carried over from the old YellowBox, but it is not clear why.
+    if (typeof args[0] === 'string' && args[0].startsWith('(ADVICE)')) {
+      return;
+    }
 
-  // We don't want to store these logs because they trigger a
-  // state update whenever we add them to the store, which is
-  // expensive to noisy logs. If we later want to display these
-  // we will store them in a different state object.
-  if (isMessageIgnored(message.content)) {
-    return;
-  }
+    // TODO: Use Error.captureStackTrace on Hermes
+    const stack = parseErrorStack(errorForStackTrace);
 
-  // If the next log has the same category as the previous one
-  // then we want to roll it up into the last log in the list
-  // by incrementing the count (simar to how Chrome does it).
-  const lastLog = Array.from(logs).pop();
-  if (lastLog && lastLog.category === category) {
-    lastLog.incrementCount();
-  } else {
-    logs.add(new LogBoxLog(level, message, stack, category, componentStack));
-  }
+    const {category, message, componentStack} = parseLogBoxLog(args);
 
-  handleUpdate();
+    // We don't want to store these logs because they trigger a
+    // state update whenever we add them to the store, which is
+    // expensive to noisy logs. If we later want to display these
+    // we will store them in a different state object.
+    if (isMessageIgnored(message.content)) {
+      return;
+    }
+
+    // If the next log has the same category as the previous one
+    // then we want to roll it up into the last log in the list
+    // by incrementing the count (simar to how Chrome does it).
+    const lastLog = Array.from(logs).pop();
+    if (lastLog && lastLog.category === category) {
+      lastLog.incrementCount();
+    } else {
+      logs.add(new LogBoxLog(level, message, stack, category, componentStack));
+    }
+
+    handleUpdate();
+  });
 }
 
 export function symbolicateLogNow(log: LogBoxLog) {

Libraries/LogBox/Data/__tests__/LogBoxData-test.js

@@ -36,13 +36,27 @@ const observe = () => {
   };
 };
 
+const logAndFlush = logs => {
+  logs.forEach(log => {
+    LogBoxData.add(log.level, log.args);
+  });
+
+  jest.runAllImmediates();
+};
+
+const logAndFlushAndUpdate = logs => {
+  logAndFlush(logs);
+
+  // We run immediates again to flush the updates.
+  jest.runAllImmediates();
+};
 describe('LogBoxData', () => {
   beforeEach(() => {
     jest.resetModules();
   });
 
   it('adds and dismisses logs', () => {
-    LogBoxData.add('warn', ['A']);
+    logAndFlush([{level: 'warn', args: ['A']}]);
 
     expect(registry().length).toBe(1);
     expect(registry()[0]).toBeDefined();
@@ -53,9 +67,11 @@ describe('LogBoxData', () => {
   });
 
   it('clears all logs', () => {
-    LogBoxData.add('warn', ['A']);
-    LogBoxData.add('warn', ['B']);
-    LogBoxData.add('warn', ['C']);
+    logAndFlush([
+      {level: 'warn', args: ['A']},
+      {level: 'warn', args: ['B']},
+      {level: 'warn', args: ['C']},
+    ]);
 
     expect(registry().length).toBe(3);
 
@@ -64,9 +80,11 @@ describe('LogBoxData', () => {
   });
 
   it('keeps logs in chronological order', () => {
-    LogBoxData.add('warn', ['A']);
-    LogBoxData.add('warn', ['B']);
-    LogBoxData.add('warn', ['C']);
+    logAndFlush([
+      {level: 'warn', args: ['A']},
+      {level: 'warn', args: ['B']},
+      {level: 'warn', args: ['C']},
+    ]);
 
     let logs = registry();
     expect(logs.length).toBe(3);
@@ -74,7 +92,7 @@ describe('LogBoxData', () => {
     expect(logs[1].category).toEqual('B');
     expect(logs[2].category).toEqual('C');
 
-    LogBoxData.add('warn', ['A']);
+    logAndFlush([{level: 'warn', args: ['A']}]);
 
     // Expect `A` to be added to the end of the registry.
     logs = registry();
@@ -86,8 +104,7 @@ describe('LogBoxData', () => {
   });
 
   it('increments the count of previous log with matching category', () => {
-    LogBoxData.add('warn', ['A']);
-    LogBoxData.add('warn', ['B']);
+    logAndFlush([{level: 'warn', args: ['A']}, {level: 'warn', args: ['B']}]);
 
     let logs = registry();
     expect(logs.length).toBe(2);
@@ -96,7 +113,7 @@ describe('LogBoxData', () => {
     expect(logs[1].category).toEqual('B');
     expect(logs[1].count).toBe(1);
 
-    LogBoxData.add('warn', ['B']);
+    logAndFlush([{level: 'warn', args: ['B']}]);
 
     // Expect `B` to be rolled into the last log.
     logs = registry();
@@ -108,9 +125,11 @@ describe('LogBoxData', () => {
   });
 
   it('ignores logs matching patterns', () => {
-    LogBoxData.add('warn', ['A!']);
-    LogBoxData.add('warn', ['B?']);
-    LogBoxData.add('warn', ['C!']);
+    logAndFlush([
+      {level: 'warn', args: ['A!']},
+      {level: 'warn', args: ['B?']},
+      {level: 'warn', args: ['C!']},
+    ]);
     expect(filteredRegistry().length).toBe(3);
 
     LogBoxData.addIgnorePatterns(['!']);
@@ -121,9 +140,12 @@ describe('LogBoxData', () => {
   });
 
   it('ignores logs matching regexs or pattern', () => {
-    LogBoxData.add('warn', ['There are 4 dogs']);
-    LogBoxData.add('warn', ['There are 3 cats']);
-    LogBoxData.add('warn', ['There are H cats']);
+    logAndFlush([
+      {level: 'warn', args: ['There are 4 dogs']},
+      {level: 'warn', args: ['There are 3 cats']},
+      {level: 'warn', args: ['There are H cats']},
+    ]);
+
     expect(filteredRegistry().length).toBe(3);
 
     LogBoxData.addIgnorePatterns(['dogs']);
@@ -137,9 +159,11 @@ describe('LogBoxData', () => {
   });
 
   it('ignores all logs when disabled', () => {
-    LogBoxData.add('warn', ['A!']);
-    LogBoxData.add('warn', ['B?']);
-    LogBoxData.add('warn', ['C!']);
+    logAndFlush([
+      {level: 'warn', args: ['A!']},
+      {level: 'warn', args: ['B?']},
+      {level: 'warn', args: ['C!']},
+    ]);
     expect(registry().length).toBe(3);
 
     LogBoxData.setDisabled(true);
@@ -150,56 +174,57 @@ describe('LogBoxData', () => {
   });
 
   it('groups consecutive logs by format string categories', () => {
-    LogBoxData.add('warn', ['%s', 'A']);
+    logAndFlush([{level: 'warn', args: ['%s', 'A']}]);
+
     expect(registry().length).toBe(1);
     expect(registry()[0].count).toBe(1);
 
-    LogBoxData.add('warn', ['%s', 'B']);
+    logAndFlush([{level: 'warn', args: ['%s', 'B']}]);
     expect(registry().length).toBe(1);
     expect(registry()[0].count).toBe(2);
 
-    LogBoxData.add('warn', ['A']);
+    logAndFlush([{level: 'warn', args: ['A']}]);
     expect(registry().length).toBe(2);
     expect(registry()[1].count).toBe(1);
 
-    LogBoxData.add('warn', ['B']);
+    logAndFlush([{level: 'warn', args: ['B']}]);
     expect(registry().length).toBe(3);
     expect(registry()[2].count).toBe(1);
   });
 
   it('groups warnings with consideration for arguments', () => {
-    LogBoxData.add('warn', ['A', 'B']);
+    logAndFlush([{level: 'warn', args: ['A', 'B']}]);
     expect(registry().length).toBe(1);
     expect(registry()[0].count).toBe(1);
 
-    LogBoxData.add('warn', ['A', 'B']);
+    logAndFlush([{level: 'warn', args: ['A', 'B']}]);
     expect(registry().length).toBe(1);
     expect(registry()[0].count).toBe(2);
 
-    LogBoxData.add('warn', ['A', 'C']);
+    logAndFlush([{level: 'warn', args: ['A', 'C']}]);
     expect(registry().length).toBe(2);
     expect(registry()[1].count).toBe(1);
 
-    LogBoxData.add('warn', ['%s', 'A', 'A']);
+    logAndFlush([{level: 'warn', args: ['%s', 'A', 'A']}]);
     expect(registry().length).toBe(3);
     expect(registry()[2].count).toBe(1);
 
-    LogBoxData.add('warn', ['%s', 'B', 'A']);
+    logAndFlush([{level: 'warn', args: ['%s', 'B', 'A']}]);
     expect(registry().length).toBe(3);
     expect(registry()[2].count).toBe(2);
 
-    LogBoxData.add('warn', ['%s', 'B', 'B']);
+    logAndFlush([{level: 'warn', args: ['%s', 'B', 'B']}]);
     expect(registry().length).toBe(4);
     expect(registry()[3].count).toBe(1);
   });
 
   it('ignores logs starting with "(ADVICE)"', () => {
-    LogBoxData.add('warn', ['(ADVICE) ...']);
+    logAndFlush([{level: 'warn', args: ['(ADVICE) ...']}]);
     expect(registry().length).toBe(0);
   });
 
   it('does not ignore logs formatted to start with "(ADVICE)"', () => {
-    LogBoxData.add('warn', ['%s ...', '(ADVICE)']);
+    logAndFlush([{level: 'warn', args: ['%s ...', '(ADVICE)']}]);
     expect(registry().length).toBe(1);
   });
 
@@ -218,9 +243,10 @@ describe('LogBoxData', () => {
     const {observer} = observe();
     expect(observer.mock.calls.length).toBe(1);
 
-    LogBoxData.add('warn', ['A']);
-    LogBoxData.add('warn', ['B']);
-    jest.runAllImmediates();
+    logAndFlushAndUpdate([
+      {level: 'warn', args: ['A']},
+      {level: 'warn', args: ['B']},
+    ]);
     expect(observer.mock.calls.length).toBe(2);
 
     // We expect observers to recieve the same Set object in sequential updates
@@ -244,8 +270,7 @@ describe('LogBoxData', () => {
     const {observer} = observe();
     expect(observer.mock.calls.length).toBe(1);
 
-    LogBoxData.add('warn', ['A']);
-    jest.runAllImmediates();
+    logAndFlushAndUpdate([{level: 'warn', args: ['A']}]);
     expect(observer.mock.calls.length).toBe(2);
 
     const lastLog = Array.from(observer.mock.calls[1][0])[0];
@@ -263,8 +288,7 @@ describe('LogBoxData', () => {
     const {observer} = observe();
     expect(observer.mock.calls.length).toBe(1);
 
-    LogBoxData.add('warn', ['A']);
-    jest.runAllImmediates();
+    logAndFlushAndUpdate([{level: 'warn', args: ['A']}]);
     expect(observer.mock.calls.length).toBe(2);
 
     LogBoxData.clear();

Libraries/LogBox/Data/__tests__/LogBoxLogParser-test.js

@@ -21,7 +21,6 @@ describe('parseLogBoxLog', () => {
   it('parses strings', () => {
     expect(parseLogBoxLog(['A'])).toEqual({
       componentStack: [],
-      stack: [],
       category: 'A',
       message: {
         content: 'A',
@@ -33,7 +32,6 @@ describe('parseLogBoxLog', () => {
   it('parses strings with arguments', () => {
     expect(parseLogBoxLog(['A', 'B', 'C'])).toEqual({
       componentStack: [],
-      stack: [],
       category: 'A B C',
       message: {
         content: 'A B C',
@@ -45,7 +43,6 @@ describe('parseLogBoxLog', () => {
   it('parses formatted strings', () => {
     expect(parseLogBoxLog(['%s', 'A'])).toEqual({
       componentStack: [],
-      stack: [],
       category: '\ufeff%s',
       message: {
         content: 'A',
@@ -62,7 +59,6 @@ describe('parseLogBoxLog', () => {
   it('parses formatted strings with insufficient arguments', () => {
     expect(parseLogBoxLog(['%s %s', 'A'])).toEqual({
       componentStack: [],
-      stack: [],
       category: '\ufeff%s %s',
       message: {
         content: 'A %s',
@@ -83,7 +79,6 @@ describe('parseLogBoxLog', () => {
   it('parses formatted strings with excess arguments', () => {
     expect(parseLogBoxLog(['%s', 'A', 'B'])).toEqual({
       componentStack: [],
-      stack: [],
       category: '\ufeff%s B',
       message: {
         content: 'A B',
@@ -100,7 +95,6 @@ describe('parseLogBoxLog', () => {
   it('treats "%s" in arguments as literals', () => {
     expect(parseLogBoxLog(['%s', '%s', 'A'])).toEqual({
       componentStack: [],
-      stack: [],
       category: '\ufeff%s A',
       message: {
         content: '%s A',
@@ -125,7 +119,6 @@ describe('parseLogBoxLog', () => {
         {component: 'MyComponent', location: 'filename.js:1'},
         {component: 'MyOtherComponent', location: 'filename2.js:1'},
       ],
-      stack: [],
       category: 'Some kind of message',
       message: {
         content: 'Some kind of message',
@@ -147,7 +140,6 @@ describe('parseLogBoxLog', () => {
         {component: 'MyComponent', location: 'filename.js:1'},
         {component: 'MyOtherComponent', location: 'filename2.js:1'},
       ],
-      stack: [],
       category:
         'Some kind of message Some other kind of message Some third kind of message',
       message: {

Libraries/LogBox/Data/parseLogBoxLog.js

@@ -12,7 +12,6 @@
 
 import UTFSequence from '../../UTFSequence';
 import stringifySafe from '../../Utilities/stringifySafe';
-import parseErrorStack from '../../Core/Devtools/parseErrorStack';
 import type {Stack} from './LogBoxSymbolication';
 
 export type Category = string;
@@ -118,7 +117,6 @@ function parseLog(
   componentStack: ComponentStack,
   category: Category,
   message: Message,
-  stack: Stack,
 |} {
   // This detects a very narrow case of a simple log string,
   // with a component stack appended by React DevTools.
@@ -152,8 +150,6 @@ function parseLog(
   return {
     ...parseCategory(argsWithoutComponentStack),
     componentStack,
-    // TODO: Use Error.captureStackTrace on Hermes
-    stack: parseErrorStack(new Error()),
   };
 }