Page MenuHomePhabricator

Test the impact of Javascript error logging on performance
Closed, ResolvedPublic4 Story Points

Description

Wrapping async callbacks into try..catch means extra operations every time a method with an async parameter is called; this might have a performance impact. We need to compare the performance with or without errorlogging (also, different implementations) for some demanding application (e.g. VisualEditor).

Related Objects

StatusAssignedTask
OpenNone
OpenNone
OpenTgr
OpenNone
OpenTgr
StalledNone
ResolvedTgr
ResolvedGilles
OpenTgr
ResolvedTgr
Resolvedcsteipp
ResolvedTgr
DeclinedTgr
StalledTgr
ResolvedTgr
ResolvedTgr
ResolvedTgr
ResolvedTgr
ResolvedTgr
OpenNone
Resolvedjcrespo
ResolvedAklapper
ResolvedTgr
ResolvedTgr

Event Timeline

Tgr created this task.Mar 14 2015, 12:53 AM
Tgr claimed this task.
Tgr raised the priority of this task from to High.
Tgr updated the task description. (Show Details)
Tgr set Security to None.
Tgr edited a custom field.
Tgr added subscribers: Aklapper, Tgr.

Change 197240 had a related patch set uploaded (by Gergő Tisza):
[WIP] Make vbench more generic

https://gerrit.wikimedia.org/r/197240

Tgr added a comment.Mar 24 2015, 12:35 AM

Chrome runs and jsbench connects to it but then gets stuck:

tgr@multimedia-jsperf:~$ sudo service jsbench-browser start
jsbench-browser start/running, process 24680
tgr@multimedia-jsperf:~$ jsbench --benchmark /usr/local/share/jsbench/ve.bench --warmups 0 --repeat 1 --jsvar stage init "http://en.wikipedia.org/wiki/Barack_Obama"
[23:30:11] Starting factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7f85611b3f80>
[23:30:11] Loading http://en.wikipedia.org/wiki/Barack_Obama...

When running chrome with X11, it gives this output:

/usr/lib/chromium-browser/chromium-browser \
      --incognito \
      --remote-debugging-port=9222 \
      --display=localhost:10.0 \
      --disable-background-networking \
      --disable-client-side-phishing-detection \
      --disable-component-update \
      --disable-default-apps \
      --disable-extensions \
      --disable-hang-monitor \
      --disable-infobars \
      --disable-plugins-discovery \
      --disable-prompt-on-repost \
      --disable-suggestions-service \
      --disable-sync \
      --disable-translate \
      --disable-v8-idle-tasks \
      --disable-web-resources \
      --no-default-browser-check \
      --no-first-run \
      `#--host-rules="MAP * localhost, EXCLUDE upload.wikimedia.org"` \
      --safebrowsing-disable-auto-update \
      --safebrowsing-disable-download-protection \
      --no-sandbox
[29072:29072:0324/003055:ERROR:browser_main_loop.cc(170)] Running without the SUID sandbox! See https://code.google.com/p/chromium/wiki/LinuxSUIDSandboxDevelopment for more information on developing with the sandbox on.
[29081:29081:0324/003055:ERROR:image_metadata_extractor.cc(111)] Couldn't load libexif.
Gtk-Message: Failed to load module "canberra-gtk-module"

(chromium-browser:29072): GLib-GIO-CRITICAL **: g_settings_schema_source_lookup: assertion 'source != NULL' failed
[29113:29113:0324/003112:ERROR:renderer_main.cc(212)] Running without renderer sandbox
libGL error: failed to open drm device: No such file or directory
libGL error: failed to load driver: i965
libGL error: dlopen /usr/lib/x86_64-linux-gnu/dri/swrast_dri.so failed (/usr/lib/x86_64-linux-gnu/dri/swrast_dri.so: cannot open shared object file: No such file or directory)
libGL error: dlopen ${ORIGIN}/dri/swrast_dri.so failed (${ORIGIN}/dri/swrast_dri.so: cannot open shared object file: No such file or directory)
libGL error: dlopen /usr/lib/dri/swrast_dri.so failed (/usr/lib/dri/swrast_dri.so: cannot open shared object file: No such file or directory)
libGL error: unable to load driver: swrast_dri.so
libGL error: failed to load driver: swrast
[29102:29102:0324/003116:ERROR:gl_context_glx.cc(54)] Failed to create GL context with glXCreateContextAttribsARB.
[29102:29102:0324/003116:ERROR:gpu_info_collector.cc(41)] gfx::GLContext::CreateGLContext failed
[29102:29102:0324/003116:ERROR:gpu_info_collector.cc(95)] Could not create context for info collection.
[29102:29102:0324/003116:ERROR:gpu_main.cc(410)] gpu::CollectGraphicsInfo failed (fatal).
[29119:29119:0324/003118:ERROR:renderer_main.cc(212)] Running without renderer sandbox
[29102:29102:0324/003120:ERROR:gpu_child_thread.cc(146)] Exiting GPU process due to errors during initialization

It opens the Obama article, loads VisualEditor and seems to get stuck there.

ori added a comment.Mar 24 2015, 3:37 AM

@Tgr: The stage should be 'activate', not 'init'; that's a typo.

Tgr added a comment.EditedMar 24 2015, 10:45 PM

Thanks! I did not realize it was waiting for the profileEnd call.

I got it working after fixing that (side note: it should probably implement the console domain, figuring out what trivial error broke the benchmark script is a pain in the ass with the current setup).

Cloning the Obama article seems like a lot of trouble so I just installed the errorlogging module from the benchmark script. That changes the timing and makes error logging less invasive, but it doesn't affect AJAX callback wrapping which is the main focus of the tests.

The results:

no JS error logging (using the bundled ve.js benchmark):

tgr@multimedia-jsperf:~$ jsbench --benchmark /usr/local/share/jsbench/ve.bench --repeat=30 --write-profile-data --jsvar stage activate "http://en.wikipedia.org/wiki/Barack_Obama"
[09:04:21] Starting factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7f57ff152fc8>
[09:04:21] Loading http://en.wikipedia.org/wiki/Barack_Obama...
[09:04:35] XX/30: CPU: 7064.00  Wall: 7406.38  GC:  225.68
[09:04:49] XX/30: CPU: 6696.68  Wall: 6985.62  GC:  164.10
[09:05:07] 01/30: CPU: 7684.31  Wall: 7987.60  GC:  284.42
[09:05:23] 02/30: CPU: 6803.36  Wall: 7020.41  GC:  194.65
[09:05:41] 03/30: CPU: 7507.66  Wall: 7962.84  GC:  248.85
[09:05:57] 04/30: CPU: 6947.71  Wall: 7183.72  GC:  199.05
[09:06:16] 05/30: CPU: 7720.77  Wall: 8016.81  GC:  263.31
[09:06:33] 06/30: CPU: 7052.47  Wall: 7360.53  GC:  178.04
[09:06:53] 07/30: CPU: 7669.57  Wall: 7995.23  GC:  248.74
[09:07:10] 08/30: CPU: 6999.31  Wall: 7234.00  GC:  195.92
[09:07:29] 09/30: CPU: 6978.29  Wall: 7225.90  GC:  230.28
[09:07:46] 10/30: CPU: 6884.41  Wall: 7089.16  GC:  173.69
[09:08:04] 11/30: CPU: 7274.42  Wall: 7548.26  GC:  258.87
[09:08:21] 12/30: CPU: 6919.64  Wall: 7163.96  GC:  186.37
[09:08:40] 13/30: CPU: 7530.06  Wall: 7849.73  GC:  252.37
[09:08:57] 14/30: CPU: 7007.76  Wall: 7206.55  GC:  179.26
[09:09:16] 15/30: CPU: 7136.39  Wall: 7469.19  GC:  223.93
[09:09:33] 16/30: CPU: 7043.23  Wall: 7243.98  GC:  195.94
[09:09:52] 17/30: CPU: 7245.87  Wall: 7588.14  GC:  246.12
[09:10:08] 18/30: CPU: 7262.74  Wall: 7463.25  GC:  198.81
[09:10:27] 19/30: CPU: 7452.95  Wall: 7749.70  GC:  239.40
[09:10:42] 20/30: CPU: 6883.85  Wall: 7234.05  GC:  178.30
[09:11:01] 21/30: CPU: 7716.30  Wall: 8067.09  GC:  256.55
[09:11:17] 22/30: CPU: 6687.46  Wall: 6907.17  GC:  179.47
[09:11:35] 23/30: CPU: 7259.97  Wall: 7519.84  GC:  225.54
[09:11:55] 24/30: CPU: 7335.36  Wall: 7614.96  GC:  211.75
[09:12:13] 25/30: CPU: 7191.57  Wall: 7489.15  GC:  208.82
[09:12:30] 26/30: CPU: 6844.47  Wall: 7060.85  GC:  182.11
[09:12:48] 27/30: CPU: 7155.16  Wall: 7348.07  GC:  181.82
[09:13:05] 28/30: CPU: 7050.29  Wall: 7277.95  GC:  171.90
[09:13:22] 29/30: CPU: 7138.57  Wall: 7522.31  GC:  273.67
[09:13:40] 30/30: CPU: 6988.31  Wall: 7254.45  GC:  181.30
[09:13:40] Stopping factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7f57ff152fc8>
[09:13:40] CPU:  min: 6687.46 max: 7720.77 avg: 7179.08 med: 7137.48 std:  283.95
[09:13:40] Wall: min: 6907.17 max: 8067.09 avg: 7455.16 med: 7411.89 std:  322.15
[09:13:41] Main loop terminated.

proxying the XHR object:

tgr@multimedia-jsperf:~$ jsbench --benchmark errorLogging.ajax.onreadystatechange.bench --repeat=30 --write-profile-data --jsvar stage activate "http://en.wikipedia.org/wiki/Barack_Obama"
[22:17:20] Starting factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7fe75f526f80>
[22:17:20] Loading http://en.wikipedia.org/wiki/Barack_Obama...
[22:17:33] XX/30: CPU: 6391.43  Wall: 6641.24  GC:  144.17
[22:17:49] XX/30: CPU: 7818.53  Wall: 8075.71  GC:  240.86
[22:18:05] 01/30: CPU: 7015.13  Wall: 7202.89  GC:  175.53
[22:18:24] 02/30: CPU: 7589.03  Wall: 7857.25  GC:  238.27
[22:18:40] 03/30: CPU: 6723.26  Wall: 6928.99  GC:  183.25
[22:18:59] 04/30: CPU: 7725.27  Wall: 8034.10  GC:  258.25
[22:19:15] 05/30: CPU: 6807.88  Wall: 6989.32  GC:  170.35
[22:19:34] 06/30: CPU: 7765.84  Wall: 8098.38  GC:  276.50
[22:19:51] 07/30: CPU: 6774.59  Wall: 6984.37  GC:  161.70
[22:20:10] 08/30: CPU: 8297.63  Wall: 8610.94  GC:  270.37
[22:20:26] 09/30: CPU: 6651.67  Wall: 6857.89  GC:  179.41
[22:20:47] 10/30: CPU: 8262.38  Wall: 8606.71  GC:  291.25
[22:21:02] 11/30: CPU: 6795.05  Wall: 7083.94  GC:  186.68
[22:21:21] 12/30: CPU: 7544.95  Wall: 7810.63  GC:  232.54
[22:21:38] 13/30: CPU: 6841.18  Wall: 7035.54  GC:  176.12
[22:21:57] 14/30: CPU: 7838.09  Wall: 8110.86  GC:  247.37
[22:22:14] 15/30: CPU: 6885.71  Wall: 7251.49  GC:  181.87
[22:22:33] 16/30: CPU: 7783.92  Wall: 8079.04  GC:  235.21
[22:22:49] 17/30: CPU: 7013.63  Wall: 7255.20  GC:  196.39
[22:23:08] 18/30: CPU: 7939.93  Wall: 8260.22  GC:  263.12
[22:23:26] 19/30: CPU: 7296.26  Wall: 7572.89  GC:  198.20
[22:23:44] 20/30: CPU: 7656.60  Wall: 7953.47  GC:  250.17
[22:24:00] 21/30: CPU: 7076.46  Wall: 7332.30  GC:  207.09
[22:24:17] 22/30: CPU: 7543.00  Wall: 7789.43  GC:  228.97
[22:24:34] 23/30: CPU: 6631.32  Wall: 6816.75  GC:  163.82
[22:24:52] 24/30: CPU: 7764.36  Wall: 8056.97  GC:  244.81
[22:25:09] 25/30: CPU: 6665.95  Wall: 6942.08  GC:  171.95
[22:25:26] 26/30: CPU: 7536.17  Wall: 7804.10  GC:  226.15
[22:25:43] 27/30: CPU: 6916.64  Wall: 7168.93  GC:  184.49
[22:26:01] 28/30: CPU: 7467.22  Wall: 7708.23  GC:  219.22
[22:26:18] 29/30: CPU: 6921.26  Wall: 7138.91  GC:  194.15
[22:26:37] 30/30: CPU: 7311.07  Wall: 7647.12  GC:  266.39
[22:26:37] Stopping factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7fe75f526f80>
[22:26:37] CPU:  min: 6631.32 max: 8297.63 avg: 7301.38 med: 7303.67 std:  487.95
[22:26:37] Wall: min: 6816.75 max: 8610.94 avg: 7566.30 med: 7610.01 std:  521.32
[22:26:38] Main loop terminated.

decorating $.Callbacks.add:

cd
tgr@multimedia-jsperf:~$ jsbench --benchmark errorLogging.ajax.callbacks.bench --repeat=30 --write-profile-data --jsvar stage activate "http://en.wikipedia.org/wiki/Barack_Obama"
[22:29:14] Starting factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7fa98b1fdfc8>
[22:29:14] Loading http://en.wikipedia.org/wiki/Barack_Obama...
[22:29:28] XX/30: CPU: 7102.29  Wall: 7527.63  GC:  239.05
[22:29:44] XX/30: CPU: 7649.42  Wall: 7962.54  GC:  289.15
[22:30:01] 01/30: CPU: 7224.10  Wall: 7487.68  GC:  213.18
[22:30:20] 02/30: CPU: 7631.13  Wall: 7966.88  GC:  273.16                      
[22:30:37] 03/30: CPU: 7329.33  Wall: 7619.65  GC:  265.81
[22:30:56] 04/30: CPU: 8297.96  Wall: 8697.89  GC:  313.26
[22:31:14] 05/30: CPU: 7507.26  Wall: 7808.12  GC:  227.24
[22:31:35] 06/30: CPU: 8183.04  Wall: 8674.91  GC:  334.87
[22:31:52] 07/30: CPU: 7184.16  Wall: 7432.36  GC:  213.39
[22:32:11] 08/30: CPU: 8313.16  Wall: 8682.76  GC:  327.13
[22:32:28] 09/30: CPU: 7255.73  Wall: 7533.87  GC:  229.42
[22:32:47] 10/30: CPU: 7799.91  Wall: 8259.18  GC:  305.74
[22:33:04] 11/30: CPU: 6886.59  Wall: 7167.56  GC:  204.26
[22:33:23] 12/30: CPU: 9238.22  Wall: 9888.30  GC:  339.34
[22:33:39] 13/30: CPU: 6656.59  Wall: 6860.21  GC:  193.28
[22:34:01] 14/30: CPU: 11129.13  Wall: 11406.59  GC:  194.93
[22:34:19] 15/30: CPU: 8831.55  Wall: 9350.28  GC:  229.91
[22:34:39] 16/30: CPU: 7749.81  Wall: 8109.10  GC:  284.58
[22:34:58] 17/30: CPU: 7433.94  Wall: 7659.94  GC:  218.53
[22:35:18] 18/30: CPU: 7829.75  Wall: 8263.51  GC:  290.06
[22:35:34] 19/30: CPU: 6936.45  Wall: 7202.19  GC:  223.93
[22:35:54] 20/30: CPU: 7550.97  Wall: 7929.04  GC:  283.07
[22:36:11] 21/30: CPU: 7014.59  Wall: 7380.47  GC:  222.95
[22:36:30] 22/30: CPU: 7183.55  Wall: 7557.20  GC:  276.84
[22:36:48] 23/30: CPU: 7029.93  Wall: 7260.20  GC:  208.27
[22:37:08] 24/30: CPU: 8401.37  Wall: 8715.28  GC:  289.58
[22:37:24] 25/30: CPU: 6942.57  Wall: 7138.02  GC:  189.40
[22:37:42] 26/30: CPU: 7228.33  Wall: 7579.50  GC:  279.74
[22:37:59] 27/30: CPU: 6699.04  Wall: 6989.81  GC:  239.35
[22:38:19] 28/30: CPU: 7810.90  Wall: 8124.00  GC:  287.81
[22:38:36] 29/30: CPU: 6766.77  Wall: 6997.97  GC:  188.17
[22:38:56] 30/30: CPU: 7423.13  Wall: 7727.57  GC:  275.47
[22:38:56] Stopping factory <__main__.ChromeRemoteDebuggingFactory instance at 0x7fa98b1fdfc8>
[22:38:56] CPU:  min: 6656.59 max: 11129.13 avg: 7648.97 med: 7428.54 std:  895.44
[22:38:56] Wall: min: 6860.21 max: 11406.59 avg: 7982.33 med: 7693.76 std:  947.77
[22:38:57] Main loop terminated.

I did not upload the cpuprofile files because they are huge (100MB gzipped), but can provide them if needed.

Tgr added a comment.Mar 24 2015, 10:58 PM

@ori, can you help evaluate the results? There seems to be a clear performance hit, and significantly bigger for the $.Callbacks.add method (+6.5% average CPU time, and tripled deviation, vs 1.7% average time and ~1.5x deviation for the proxy-based method) but I don't know what level of slowdown counts as acceptable.

Tgr added a comment.Mar 25 2015, 3:18 AM

Discussed with Ori, performance impact is no big deal but async JS wrapping is pushed back (maybe abandoned) due to maintainability/compatibility concerns.

Tgr added a comment.Mar 25 2015, 3:34 AM
In T92701#1146920, @Tgr wrote:

(side note: it should probably implement the console domain, figuring out what trivial error broke the benchmark script is a pain in the ass with the current setup)

Just needed to be added to the whitelist, fixed in the latest version of the patch.

Gilles added a subscriber: Gilles.Mar 31 2015, 2:27 PM

Does this still need review?

Tgr added a comment.EditedMar 31 2015, 4:01 PM

Yes, but it's not blocking anything, it's just to make the life of the next person doing JS performance tests easier. The bug itself could be closed I guess.

Tgr closed this task as Resolved.Apr 3 2015, 6:29 AM

Change 197240 merged by Ori.livneh:
Make vbench more generic

https://gerrit.wikimedia.org/r/197240