Page MenuHomePhabricator
Create Task
Maniphest T92701

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

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).

Details

ProjectBranchLines +/-Subject
operations/puppetproduction+216 -124Make vbench more generic
Customize query in gerrit

Related Objects
Search...

StatusSubtypeAssignedTask
 OpenNoneT106913 Use Sentry on non-production Wikimedia wikis, Toolforge and other sites/tools
 DeclinedNoneT106915 Use Sentry in production
 DeclinedTgrT91649 Deploy Sentry (JavaScript error logging) to production, configured to log only a limited subset of users/pages
 Resolved• jlinehanT88399 Improve Javascript error logging coverage
 DeclinedNoneT382 RfC: Server-side Javascript error logging
 DeclinedNoneT513 Wrap scripts with exception handling for automatic JS error logging
 ResolvedTgrT524 Interface to display JS error logs
 Resolved• GillesT525 Review existing JS error logging solutions
 ResolvedTgrT1345 Set up and test Sentry on Labs for JS error logging
 ResolvedTgrT78807 Deploy Sentry extension on beta cluster
 ResolvedcsteippT86677 Quick/short security review of Extension:Sentry
 ResolvedTgrT78809 Implement module wrapping for Sentry
 DeclinedTgrT85262 Add startup script to automatically wrap asynchronous functions in try..catch
 DeclinedTgrT92247 Wrap jQuery AJAX callbacks in try..catch via mw.errorLogging
 ResolvedTgrT92701 Test the impact of Javascript error logging on performance
 ResolvedTgrT85263 Track module initialization errors in ResourceLoader
 ResolvedTgrT84957 Vagrantize Sentry
 ResolvedTgrT90773 Fix log directory permissions in Sentry vagrant role
 ResolvedTgrT84956 Create basic puppet role for Sentry
 ResolvedjcrespoT112228 Need to run postgresql::user twice to set the password
 ResolvedAklapperT84955 Create MediaWiki-extensions-Sentry project
 ResolvedTgrT89384 Add error id generation to mw.errorLogging
 ResolvedTgrT105374 Investigate if the XSS vulnerability addressed in Sentry 7.6.1 affects us

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 added projects: Multimedia-Sprint-2015-03-11, Multimedia, Sentry.
Tgr set Security to None.
Tgr edited a custom field.
Tgr added subscribers: Aklapper, Tgr.
Krinkle added subscribers: ori, Krinkle.Mar 14 2015, 1:14 AM
gerritbot added a subscriber: gerritbot.Mar 16 2015, 10:32 PM

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

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

gerritbot added a project: Patch-For-Review.Mar 16 2015, 10:32 PM
• Gilles edited projects, added Multimedia-Sprint-2015-03-18; removed Multimedia-Sprint-2015-03-11.Mar 18 2015, 4:14 PM
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:

errorLogging.ajax.onreadystatechange.bench8 KBDownload

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:

errorLogging.ajax.callbacks.bench7 KBDownload

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 moved this task from Backlog to Needs code review on the Multimedia-Sprint-2015-03-18 board.Mar 25 2015, 3:28 AM
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 edited projects, added Multimedia-Sprint-2015-03-25; removed Multimedia-Sprint-2015-03-18.Mar 25 2015, 3:44 PM
• Gilles moved this task from Backlog to Needs code review on the Multimedia-Sprint-2015-03-25 board.Mar 25 2015, 3:48 PM
• 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
gerritbot added a comment.Apr 3 2015, 8:50 PM

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

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

Tgr mentioned this in rOPUP0ceb7a74d450: Make vbench more generic.Apr 3 2015, 8:50 PM
Content licensed under Creative Commons Attribution-ShareAlike 4.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL