Issue metadata
Sign in to add a comment
|
Service worker takes 2s to serve worker script
Reported by
a...@scirra.com,
Apr 20 2017
|
||||||||||||||||||||||
Issue descriptionUserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3075.0 Safari/537.36 Steps to reproduce the problem: We recently launched a PWA. One of our locally cached worker scripts takes 2s to be served by the service worker on a high-end desktop machine. It appears to completely block all requests through the SW, making an obvious freeze in loading progress. We've had reports from other users that this blocking can take as long as 15 seconds. 1. Visit our PWA at https://editor.construct.net 2. Wait for "available offline" notification in lower left 3. Open dev tools network panel and record a reload of the page. 4. Look for results for dispatchWorker.js and jobWorker.js. On my machine I see results that look like this: https://www.dropbox.com/s/zdek5si1iig1yko/chrome-sw-worker.png?dl=0 What is the expected behavior? The service worker should be able to serve scripts from cache quickly, definitely <100ms on a powerful machine. What went wrong? The web worker script takes seconds to be served by the SW. There also does not appear to be any diagnostic indicating why it is taking so long. Did this work before? N/A Chrome version: 60.0.3075.0 Channel: canary OS Version: 10.0 Flash Version: The web worker script does use importScripts() to bring in some heavyweight scripts, such as an asm.js compiled version of ffmpeg for audio encoding. However these scripts are lazy-loaded in the worker on first use, i.e. they only call importScripts() the first time that task is actually run. Following the steps above does not cause these workers to do any work, so they won't call importScripts() on any heavy scripts. Perhaps the SW is trying to do something like a blocking compilation of all the scripts the worker could possibly import, even before it's imported them. The intent here is to pre-load the workers so they are ready as soon as the user does something. We could delay loading to the first time a job is posted, but then this moves seconds of latency to just after a user action, where it will be highly noticable. It's also surprising that this is apparently blocking behavior - SW's APIs are all async, so what exactly is blocking other requests getting through the SW? As the picture shows, later requests (e.g. search-icon.svg, which is < 1kb) end up taking ~1s to be processed through the SW.
,
Apr 21 2017
This is because the fetch() API call in the service worker is blocked by the busy main thread. I can see the requests of dispatchWorker.js and jobWorker.js from the service worker in the bottom of the screenshot. If these scripts are in CacheStorage, and the service worker serve them to the page, the worker can start quickly.
,
Apr 21 2017
horo@ - but the main thread appears to be idle during the SW request, as shown here: https://dl.dropboxusercontent.com/u/15217362/chrome-sw-idle.png So maybe this is actually a different problem to issue 443374 ?
,
Apr 21 2017
Ah yes. The busy main thread may not be the root cause. Could you send chrome://tracing/ log? - Open chrome://tracing/ - Click "Record" - Select "Manually select settings" - Select all "Record Categories" - Click "Record" - Reload the site - Click "Stop" - Click "Save"
,
Apr 21 2017
Trace: https://dl.dropboxusercontent.com/u/15217362/trace_editor-construct-net.json.gz (Meta: I also got an error at the top of the tracing window: "Import Warning: UserModelBuilder: Please file a bug with this trace: double-handled event:MouseLeave@1405.875")
,
Apr 21 2017
The Cache Thread gets super busy to write something to disk just before loading dispatchWorker.js. Does your site write something to the disk during the page load? Is there any anti virus software installed? If so, please try disabling the anti virus software.
,
Apr 21 2017
,
Apr 21 2017
,
Apr 21 2017
It still happens with Windows Defender disabled on my Windows 10 system. The SW should be read-only when starting up. You can see the script we use here: https://github.com/AshleyScirra/scirra-offline-sw Basically it only does writes on the first load, and it shows the "available offline" notification when those writes are done. When the page reloads, the SW is read-only from the cache, and as you'd expect for an offline-first PWA, every resource is served by the SW.
,
Apr 21 2017
re: comment #6: This is pretty weird --- it looks like something is creating and destroying the cache backend a lot --- a quick grep suggests 4772 calls to SimpleBackendImpl::Init.
,
Apr 21 2017
Pardon me, 1356, which doesn't qualitatively change things.
,
Apr 21 2017
I can "only" see ~100 invocations per load, which all seem to be going via CacheStorage::SimpleCacheLoader::CreateCache -> CacheStorageCache::CreatePersistentCache, with the same cache path (from some debug output I added): [13876:13904:0421/164736.368608:ERROR:cache_storage.cc(240)] Looked up:c3-https://editor.construct.net/r21/-v2100 => 4c032fac-a2d8-4376-b90d-3c2c55cf8da2 [13876:13904:0421/164736.368961:ERROR:simple_backend_impl.cc(257)] Create SimpleBackendImpl for:/tmp/prof/Default/Service Worker/CacheStorage/7774cba7b75ccfeaf41cf538d2ef930530d17171/4c032fac-a2d8-4376-b90d-3c2c55cf8da2 from #0 0x7f4830bc358b base::debug::StackTrace::StackTrace() #1 0x7f4830bc228c base::debug::StackTrace::StackTrace() #2 0x7f482fe62a98 disk_cache::SimpleBackendImpl::SimpleBackendImpl() #3 0x7f482fe4ee0f (anonymous namespace)::CacheCreator::Run() #4 0x7f482fe4ec3d disk_cache::CreateCacheBackend() #5 0x7f482a154330 content::CacheStorageCache::CreateBackend() I know nothing of this code, so hopefully some who does will chime in.
,
Apr 21 2017
Also destruction follows creation, via: (I think it's even less readable when fully demangled): [15693:15766:0421/170029.877706:ERROR:simple_backend_impl.cc(262)] ~SimpleBackendImpl for:/tmp/prof/Default/Service Worker/CacheStorage/7774cba7b75ccfeaf41cf538d2ef930530d17171/4c032fac-a2d8-4376-b90d-3c2c55cf8da2 from #0 0x7f60a11c158b base::debug::StackTrace::StackTrace() #1 0x7f60a11c028c base::debug::StackTrace::StackTrace() #2 0x7f60a046152c disk_cache::SimpleBackendImpl::~SimpleBackendImpl() #3 0x7f60a04616e9 disk_cache::SimpleBackendImpl::~SimpleBackendImpl() #4 0x7f609991bb2f std::default_delete<>::operator()() #5 0x7f609a3f7d43 std::unique_ptr<>::~unique_ptr() #6 0x7f609a74c490 content::CacheStorageCache::~CacheStorageCache() #7 0x7f609a74c4b9 content::CacheStorageCache::~CacheStorageCache() #8 0x7f609991bb2f std::default_delete<>::operator()() #9 0x7f609a7220ec std::unique_ptr<>::reset() #10 0x7f609a71e1ad content::CacheStorage::DropCacheHandleRef() #11 0x7f609a779c4f content::CacheStorageCacheHandle::~CacheStorageCacheHandle() #12 0x7f609a731f0b std::default_delete<>::operator()() #13 0x7f609a71fe33 std::unique_ptr<>::~unique_ptr() #14 0x7f609a743463 _ZN4base8internal13FunctorTraitsIMN7content12CacheStorageEFvSt10unique_ptrINS2_23CacheStorageCacheHandleESt14default_deleteIS5_EEPNS3_18CacheMatchResponseERKNS_8CallbackIFvvELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEENS2_17CacheStorageErrorES4_INS2_21ServiceWorkerResponseES6_ISJ_EES4_IN7storage14BlobDataHandleES6_ISN_EEEvE6InvokeIRKNS_7WeakPtrIS3_EEJS8_RKSA_SH_SI_SL_SP_EEEvSR_OT_DpOT0_ #15 0x7f609a74321a _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content12CacheStorageEFvSt10unique_ptrINS4_23CacheStorageCacheHandleESt14default_deleteIS7_EEPNS5_18CacheMatchResponseERKNS_8CallbackIFvvELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEENS4_17CacheStorageErrorES6_INS4_21ServiceWorkerResponseES8_ISL_EES6_IN7storage14BlobDataHandleES8_ISP_EEERKNS_7WeakPtrIS5_EEJSA_RKSC_SJ_SK_SN_SR_EEEvOT_OT0_DpOT1_ #16 0x7f609a7430fd _ZN4base8internal7InvokerINS0_9BindStateIMN7content12CacheStorageEFvSt10unique_ptrINS3_23CacheStorageCacheHandleESt14default_deleteIS6_EEPNS4_18CacheMatchResponseERKNS_8CallbackIFvvELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEENS3_17CacheStorageErrorES5_INS3_21ServiceWorkerResponseES7_ISK_EES5_IN7storage14BlobDataHandleES7_ISO_EEEJNS_7WeakPtrIS4_EENS0_13PassedWrapperIS9_EESB_SG_EEEFvSJ_SM_SQ_EE7RunImplIRKSS_RKSt5tupleIJSU_SW_SB_SG_EEJLm0ELm1ELm2ELm3EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEEOSJ_OSM_OSQ_ #17 0x7f609a742f53 _ZN4base8internal7InvokerINS0_9BindStateIMN7content12CacheStorageEFvSt10unique_ptrINS3_23CacheStorageCacheHandleESt14default_deleteIS6_EEPNS4_18CacheMatchResponseERKNS_8CallbackIFvvELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEENS3_17CacheStorageErrorES5_INS3_21ServiceWorkerResponseES7_ISK_EES5_IN7storage14BlobDataHandleES7_ISO_EEEJNS_7WeakPtrIS4_EENS0_13PassedWrapperIS9_EESB_SG_EEEFvSJ_SM_SQ_EE3RunEPNS0_13BindStateBaseEOSJ_OSM_OSQ_ #18 0x7f609a720e7e _ZNKR4base8CallbackIFvN7content17CacheStorageErrorESt10unique_ptrINS1_21ServiceWorkerResponseESt14default_deleteIS4_EES3_IN7storage14BlobDataHandleES5_IS9_EEELNS_8internal8CopyModeE1ELNSD_10RepeatModeE1EE3RunES2_S7_SB_ #19 0x7f609a735f95 _ZN7content21CacheStorageScheduler19RunNextContinuationIJNS_17CacheStorageErrorESt10unique_ptrINS_21ServiceWorkerResponseESt14default_deleteIS4_EES3_IN7storage14BlobDataHandleES5_IS9_EEEEEvRKN4base8CallbackIFvDpT_ELNSC_8internal8CopyModeE1ELNSH_10RepeatModeE1EEESF_ #20 0x7f609a736436 _ZN4base8internal13FunctorTraitsIMN7content21CacheStorageSchedulerEFvRKNS_8CallbackIFvNS2_17CacheStorageErrorESt10unique_ptrINS2_21ServiceWorkerResponseESt14default_deleteIS7_EES6_IN7storage14BlobDataHandleES8_ISC_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES5_SA_SE_EvE6InvokeIRKNS_7WeakPtrIS3_EEJSK_S5_SA_SE_EEEvSM_OT_DpOT0_ #21 0x7f609a7362e2 _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content21CacheStorageSchedulerEFvRKNS_8CallbackIFvNS4_17CacheStorageErrorESt10unique_ptrINS4_21ServiceWorkerResponseESt14default_deleteIS9_EES8_IN7storage14BlobDataHandleESA_ISE_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES7_SC_SG_ERKNS_7WeakPtrIS5_EEJSM_S7_SC_SG_EEEvOT_OT0_DpOT1_ #22 0x7f609a736212 _ZN4base8internal7InvokerINS0_9BindStateIMN7content21CacheStorageSchedulerEFvRKNS_8CallbackIFvNS3_17CacheStorageErrorESt10unique_ptrINS3_21ServiceWorkerResponseESt14default_deleteIS8_EES7_IN7storage14BlobDataHandleES9_ISD_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES6_SB_SF_EJNS_7WeakPtrIS4_EESJ_EEESG_E7RunImplIRKSN_RKSt5tupleIJSP_SJ_EEJLm0ELm1EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEEOS6_OSB_OSF_ #23 0x7f609a7360f3 _ZN4base8internal7InvokerINS0_9BindStateIMN7content21CacheStorageSchedulerEFvRKNS_8CallbackIFvNS3_17CacheStorageErrorESt10unique_ptrINS3_21ServiceWorkerResponseESt14default_deleteIS8_EES7_IN7storage14BlobDataHandleES9_ISD_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES6_SB_SF_EJNS_7WeakPtrIS4_EESJ_EEESG_E3RunEPNS0_13BindStateBaseEOS6_OSB_OSF_ #24 0x7f609a720e7e _ZNKR4base8CallbackIFvN7content17CacheStorageErrorESt10unique_ptrINS1_21ServiceWorkerResponseESt14default_deleteIS4_EES3_IN7storage14BlobDataHandleES5_IS9_EEELNS_8internal8CopyModeE1ELNSD_10RepeatModeE1EE3RunES2_S7_SB_ #25 0x7f609a74f521 content::CacheStorageCache::MatchDidMatchAll() #26 0x7f609a75cd86 _ZN4base8internal13FunctorTraitsIMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS2_17CacheStorageErrorESt10unique_ptrINS2_21ServiceWorkerResponseESt14default_deleteIS7_EES6_IN7storage14BlobDataHandleES8_ISC_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES5_S6_INSt7__debug6vectorIS7_SaIS7_EEES8_ISO_EES6_INSM_ISE_SaISE_EEES8_ISS_EEEvE6InvokeIRKNS_7WeakPtrIS3_EEJSK_S5_SQ_SU_EEEvSW_OT_DpOT0_ #27 0x7f609a75cc32 _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS4_17CacheStorageErrorESt10unique_ptrINS4_21ServiceWorkerResponseESt14default_deleteIS9_EES8_IN7storage14BlobDataHandleESA_ISE_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES7_S8_INSt7__debug6vectorIS9_SaIS9_EEESA_ISQ_EES8_INSO_ISG_SaISG_EEESA_ISU_EEERKNS_7WeakPtrIS5_EEJSM_S7_SS_SW_EEEvOT_OT0_DpOT1_ #28 0x7f609a76abf2 _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS3_17CacheStorageErrorESt10unique_ptrINS3_21ServiceWorkerResponseESt14default_deleteIS8_EES7_IN7storage14BlobDataHandleES9_ISD_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES6_S7_INSt7__debug6vectorIS8_SaIS8_EEES9_ISP_EES7_INSN_ISF_SaISF_EEES9_IST_EEEJNS_7WeakPtrIS4_EESJ_EEEFvS6_SR_SV_EE7RunImplIRKSX_RKSt5tupleIJSZ_SJ_EEJLm0ELm1EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEEOS6_OSR_OSV_ #29 0x7f609a76aad3 _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS3_17CacheStorageErrorESt10unique_ptrINS3_21ServiceWorkerResponseESt14default_deleteIS8_EES7_IN7storage14BlobDataHandleES9_ISD_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES6_S7_INSt7__debug6vectorIS8_SaIS8_EEES9_ISP_EES7_INSN_ISF_SaISF_EEES9_IST_EEEJNS_7WeakPtrIS4_EESJ_EEEFvS6_SR_SV_EE3RunEPNS0_13BindStateBaseEOS6_OSR_OSV_ #30 0x7f609a7530fe _ZNKR4base8CallbackIFvN7content17CacheStorageErrorESt10unique_ptrINSt7__debug6vectorINS1_21ServiceWorkerResponseESaIS6_EEESt14default_deleteIS8_EES3_INS5_IS3_IN7storage14BlobDataHandleES9_ISD_EESaISF_EEES9_ISH_EEELNS_8internal8CopyModeE1ELNSL_10RepeatModeE1EE3RunES2_SB_SJ_ #31 0x7f609a74f812 content::CacheStorageCache::MatchAllDidQueryCache() #32 0x7f609a76b319 _ZN4base8internal13FunctorTraitsIMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS2_17CacheStorageErrorEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES5_St10unique_ptrINSt7__debug6vectorINS3_16QueryCacheResultESaISF_EEESt14default_deleteISH_EEEvE6InvokeIRKNS_7WeakPtrIS3_EEJSB_S5_SK_EEEvSM_OT_DpOT0_ #33 0x7f609a76b219 _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS4_17CacheStorageErrorEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES7_St10unique_ptrINSt7__debug6vectorINS5_16QueryCacheResultESaISH_EEESt14default_deleteISJ_EEERKNS_7WeakPtrIS5_EEJSD_S7_SM_EEEvOT_OT0_DpOT1_ #34 0x7f609a76b15d _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS3_17CacheStorageErrorESt10unique_ptrINSt7__debug6vectorINS3_21ServiceWorkerResponseESaISA_EEESt14default_deleteISC_EES7_INS9_IS7_IN7storage14BlobDataHandleESD_ISH_EESaISJ_EEESD_ISL_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES6_S7_INS9_INS4_16QueryCacheResultESaISU_EEESD_ISW_EEEJNS_7WeakPtrIS4_EESR_EEEFvS6_SY_EE7RunImplIRKS10_RKSt5tupleIJS12_SR_EEJLm0ELm1EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEEOS6_OSY_ #35 0x7f609a76b04e _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvRKNS_8CallbackIFvNS3_17CacheStorageErrorESt10unique_ptrINSt7__debug6vectorINS3_21ServiceWorkerResponseESaISA_EEESt14default_deleteISC_EES7_INS9_IS7_IN7storage14BlobDataHandleESD_ISH_EESaISJ_EEESD_ISL_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEES6_S7_INS9_INS4_16QueryCacheResultESaISU_EEESD_ISW_EEEJNS_7WeakPtrIS4_EESR_EEEFvS6_SY_EE3RunEPNS0_13BindStateBaseEOS6_OSY_ #36 0x7f609a754079 _ZNKR4base8CallbackIFvN7content17CacheStorageErrorESt10unique_ptrINSt7__debug6vectorINS1_17CacheStorageCache16QueryCacheResultESaIS7_EEESt14default_deleteIS9_EEELNS_8internal8CopyModeE1ELNSE_10RepeatModeE1EE3RunES2_SC_ #37 0x7f609a74ce5e content::CacheStorageCache::QueryCacheDidOpenFastPath() #38 0x7f609a764c0b _ZN4base8internal13FunctorTraitsIMN7content17CacheStorageCacheEFvSt10unique_ptrINS3_17QueryCacheContextESt14default_deleteIS5_EEiEvE6InvokeIRKNS_7WeakPtrIS3_EEJS8_iEEEvSA_OT_DpOT0_ #39 0x7f609a764ac4 _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content17CacheStorageCacheEFvSt10unique_ptrINS5_17QueryCacheContextESt14default_deleteIS7_EEiERKNS_7WeakPtrIS5_EEJSA_iEEEvOT_OT0_DpOT1_ #40 0x7f609a764a18 _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvSt10unique_ptrINS4_17QueryCacheContextESt14default_deleteIS6_EEiEJNS_7WeakPtrIS4_EENS0_13PassedWrapperIS9_EEEEEFviEE7RunImplIRKSB_RKSt5tupleIJSD_SF_EEJLm0ELm1EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEEOi #41 0x7f609a76491c _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvSt10unique_ptrINS4_17QueryCacheContextESt14default_deleteIS6_EEiEJNS_7WeakPtrIS4_EENS0_13PassedWrapperIS9_EEEEEFviEE3RunEPNS0_13BindStateBaseEOi #42 0x7f609a335fc1 _ZNKR4base8CallbackIFviELNS_8internal8CopyModeE1ELNS2_10RepeatModeE1EE3RunEi #43 0x7f609a74ccec content::CacheStorageCache::QueryCache() #44 0x7f609a749e26 content::CacheStorageCache::MatchAllImpl() #45 0x7f609a749a23 content::CacheStorageCache::MatchImpl() #46 0x7f609a737cb4 _ZN4base8internal13FunctorTraitsIMN7content12CacheStorageEFvSt10unique_ptrINS2_25ServiceWorkerFetchRequestESt14default_deleteIS5_EERKNS2_28CacheStorageCacheQueryParamsERKNS_8CallbackIFvNS2_17CacheStorageErrorES4_INS2_21ServiceWorkerResponseES6_ISE_EES4_IN7storage14BlobDataHandleES6_ISI_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEEEvE6InvokeIRKNS_7WeakPtrIS3_EEJS8_SB_SQ_EEEvSS_OT_DpOT0_ #47 0x7f609a75bca9 _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content17CacheStorageCacheEFvSt10unique_ptrINS4_25ServiceWorkerFetchRequestESt14default_deleteIS7_EERKNS4_28CacheStorageCacheQueryParamsERKNS_8CallbackIFvNS4_17CacheStorageErrorES6_INS4_21ServiceWorkerResponseES8_ISG_EES6_IN7storage14BlobDataHandleES8_ISK_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEEERKNS_7WeakPtrIS5_EEJSA_SD_SS_EEEvOT_OT0_DpOT1_ #48 0x7f609a75bbe5 _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvSt10unique_ptrINS3_25ServiceWorkerFetchRequestESt14default_deleteIS6_EERKNS3_28CacheStorageCacheQueryParamsERKNS_8CallbackIFvNS3_17CacheStorageErrorES5_INS3_21ServiceWorkerResponseES7_ISF_EES5_IN7storage14BlobDataHandleES7_ISJ_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEEEJNS_7WeakPtrIS4_EENS0_13PassedWrapperIS9_EESA_SP_EEEFvvEE7RunImplIRKST_RKSt5tupleIJSV_SX_SA_SP_EEJLm0ELm1ELm2ELm3EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEE #49 0x7f609a75ba7c _ZN4base8internal7InvokerINS0_9BindStateIMN7content17CacheStorageCacheEFvSt10unique_ptrINS3_25ServiceWorkerFetchRequestESt14default_deleteIS6_EERKNS3_28CacheStorageCacheQueryParamsERKNS_8CallbackIFvNS3_17CacheStorageErrorES5_INS3_21ServiceWorkerResponseES7_ISF_EES5_IN7storage14BlobDataHandleES7_ISJ_EEELNS0_8CopyModeE1ELNS0_10RepeatModeE1EEEEJNS_7WeakPtrIS4_EENS0_13PassedWrapperIS9_EESA_SP_EEEFvvEE3RunEPNS0_13BindStateBaseE #50 0x7f6099924a1d _ZNKR4base8CallbackIFvvELNS_8internal8CopyModeE1ELNS2_10RepeatModeE1EE3RunEv #51 0x7f609a7a418d content::CacheStorageOperation::Run() #52 0x7f6099941a07 _ZN4base8internal13FunctorTraitsIMN7content13URLLoaderImplEFvvEvE6InvokeIRKNS_7WeakPtrIS3_EEJEEEvS5_OT_DpOT0_ #53 0x7f609a7a46da _ZN4base8internal12InvokeHelperILb1EvE8MakeItSoIRKMN7content21CacheStorageOperationEFvvERKNS_7WeakPtrIS5_EEJEEEvOT_OT0_DpOT1_ #54 0x7f609a7a4662 _ZN4base8internal7InvokerINS0_9BindStateIMN7content21CacheStorageOperationEFvvEJNS_7WeakPtrIS4_EEEEEFvvEE7RunImplIRKS6_RKSt5tupleIJS8_EEJLm0EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEE #55 0x7f609a7a45ac _ZN4base8internal7InvokerINS0_9BindStateIMN7content21CacheStorageOperationEFvvEJNS_7WeakPtrIS4_EEEEEFvvEE3RunEPNS0_13BindStateBaseE #56 0x7f60a11c7a9e _ZNO4base8CallbackIFvvELNS_8internal8CopyModeE0ELNS2_10RepeatModeE0EE3RunEv #57 0x7f60a11c71de base::debug::TaskAnnotator::RunTask() #58 0x7f60a1259e6d base::MessageLoop::RunTask() #59 0x7f60a125a0f4 base::MessageLoop::DeferOrRunPendingTask() #60 0x7f60a125a3e4 base::MessageLoop::DoWork() #61 0x7f60a12749de base::MessagePumpLibevent::Run() ... And this is definitely where I have to punt it to someone who understands CacheStorage.
,
Apr 24 2017
From initial tracing... I think the CacheStorageCache creation/destruction might be a red herring. When I load the page there's a long (multi-second) sequence where it's loading from an existing cache which has the cache instance in memory. That's followed by (I think) the script's cache upgrade sequence where it is trying to access a new cache; after each operation the handles are getting dropped so it is flushed from memory and re-created each time. That only takes a fraction of a second, though, so I'm not sure it's to blame...
,
Apr 24 2017
Nonetheless, it would probably be good to avoid unnecessary create/delete cycles even if that isn't the root cause of the slowness. @jsbell, would it be possible to work-around the create/delete behavior with a small change to script? A change that keeps a reference to the Cache object for the duration of the upgrade sequence?
,
May 8 2017
Any news on this? It's still affecting our PWA.
,
May 8 2017
,
May 9 2017
Let's file a separate bug for the cache reopening. Anytime we return a cache handle to the renderer the browser process keeps that handle alive for 30 seconds to prevent this kind of thrashing. Sounds like we're either missing a case or the browser is making some caches on the renderer's behalf for some operation but not returning it so it doens't get held. In terms of this bug, it looks to me (at first glance) like a classic case of a busy IO thread. A *lot* (972) of resources are loaded at once, which leads to all of those resources following each other through the URLRequest async states. This means that the first request (e.g., high priority javascript) has to wait for the remaining several hundred resources to go through its network request start states etc. So, amortized, each request might take a reasonable amount of time, but the TTFB for the early requests suffers greatly. One way to fix this is to throttle service worker requests just like we did for H2+QUIC requests in issue 655585.
,
May 10 2017
I filed issue 720784 re: cache re-opening.
,
May 12 2017
715640 is working on re-architecting how service worker intercepts requests. We might need to do some throttling there as well.
,
Jun 20 2017
This has gotten much worse in Canary! My measurements are: Chrome 59.0.3071.104 (stable): ~3 seconds Chrome 61.0.3135.4 (canary): ~20 seconds Please do something about this - it renders our PWA entirely responsive for a long time even on a high-end desktop machine!
,
Jul 21 2017
Canary 61.0.3163.0 is still a lot slower!
,
Aug 21 2017
Canary 62.0.3192.0 currently taking ~14 seconds.
,
Oct 31 2017
As of 64.0.3254.0 (canary), the scripts are now taking ~7 seconds to load.
,
Dec 7 2017
Still takes over 3 seconds to serve in 65.0.3287.0 (canary) with i7-6700K @ 4 GHz.
,
Dec 14 2017
,
Aug 2
,
Aug 31
Is this still happening? I just tested on 67 and trunk, but I'm not able to reproduce. It looks like the SW might be doing a pass-through fetch instead of hitting cache_storage now, though.
,
Oct 4
It takes 500ms in Chrome 69 for me now on a high-end desktop. The page's "request to service worker" takes ~500ms, but the actual fetch from the service worker takes 3ms and serves from disk cache, according to the network panel. So it still seems to be unusually slow.
,
Oct 4
I'm using a medium to high-end desktop PC with Chrome 69.0.3497.100 and it takes about 6000ms on my end. It's really a bummer that Chrome's SW implementation is slowing down Construct 3 because the PWA itself, is blazingly fast in terms of load times. In the attachments is a comparison between Chrome and FireFox SW performance, which makes it clear that this is quite an impactful issue.
,
Oct 4
Is there any improvement on chrome canary 71? We've made some changes to cache_storage and service workers there that might help. Also, FWIW we will be continuing to make changes in these areas in the near future.
,
Oct 4
Tested using Canary 71.0.3570.0 and I can confirm a huge improvement. SW loads and does the work in less than 1000ms there. Can we expect those changes that were made to go stable soon?
,
Oct 4
Its difficult to say without knowing exactly which changes made the impact. Some things might be coming in earlier in 70 or rolled out more slowly. Chrome 71 is currently scheduled to release on Dec 4, though.
,
Oct 4
Testing in Canary 71.0.3570.0 and yes, it does look better - just a few ms for both the page and SW request. So looks like it's all sorted!
,
Oct 4
Ok, I'm going to close this bug for now then. Please re-open or file a new bug if the problem returns. Thanks! |
|||||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||||
Comment 1 by mmenke@chromium.org
, Apr 20 2017