Themekit: Large CPU consumption with theme watch

[samueltlg]

Describe the bug
When running theme watch for a project with the following ignore_files setting in config.yml (no other settings aside from essential)..

  ignore_files:
    - config/*
    - notes/*
    - node_modules/*
    - ./package.json
    - ./package.lock.json
    - prepros*
    - ./.vscode/*
    - liquid-testing/*
    - local-files/*
    - ./README.md
    - tests/*
    - src/*
    - webpack*.js
    - ./tsconfig.json

CPU usage starts and remains at at-least 15% - remaining between here and 21% - ish. I am using a fairly fast machine - see specs below.

Is is worth noting that the total project folder size is 141MB. 128MB belongs in the node_modules folder (which is ignored), and a lot of the remaining 13MB is also ignored in the other ignored directories. This only leaves a few MB of project files left that are being watched.

To Reproduce
Steps to reproduce the behavior:

1. Run command 'theme watch'.

Expected behavior
A low CPU usage, as is typically reported.

Environment (please complete the following information):

• OS [e.g. iOS]: WIndows 10 (latest developers build)
  
  
  
  • Themekit version [e.g. v0.7.5]: 1.0.1
  
  
• Editor [e.g. atom, sublime]: VS Code 1.38.1
• Machine Specs
  
  
  
  • Processor: Processor Intel(R) Core(TM) i7-8565U CPU @ 1.80GHz, 1992 Mhz, 4 Core(s), 8 Logical Processor(s)
  
  
  • RAM: 16GB DDR4 2200MHz
  
  

[samueltlg]

Any idea what is going on here? Seems quite mad that there is such high CPU usage.
The problem still persists whether running theme watch from WSL or windows, and still persists when all editors (Including the workspace) are closed. If also still persists regardless of whether the ignore_files option is supplied in config.yml. And the ignore_files option does work when the file paths are supplied

[tanema]

We, there may be an issue with the ignore patterns on watch for windows currently, I should be able to have a pre-release for you today or tomorrow for you to see if it fixes the issue for you.

[samueltlg]

Nice one, thanks!

[tanema]

Okay try updating to the patch version with theme update --verison=v1.0.2-issue664

[samueltlg]

Just tried it running both through WSL and windows git bash. It looks like the issue is still persisting, with CPU usage starting and remaining at ~20+%

EDIT: Although running the above update command reports a successful update, running 'theme version' comes back with version 1.0.1 (on both Windows/WSL), if that signal anything..

[tanema]

yes that is to be expected because it is pre-release

[whalesalad]

I am having the same issue on a 2018 Macbook Pro, but perhaps worse.

In my config, I am ignoring node_modules. If I run the tree command to mimic that, I get 9 directories, 237 files as output.

Here is some system info:

OS: macOS Mojave 10.14.6 18G1012 x86_64
Host: MacBookPro15,1
Kernel: 18.7.0
CPU: Intel i7-8750H (12) @ 2.20GHz

theme watch immediately jumps to ~50% CPU and will remain there, rarely dropping under 40% usage. It turns my Mac into a space heater!

For fun, I started a 30 second timer and then looked at the # of syscalls the theme binary had made during that time frame. Activity Monitor is reporting 2,394,426.

[whalesalad]

Perhaps it is worth looking at https://github.com/fsnotify/fsnotify as a backing filesystem watcher as opposed to https://github.com/radovskyb/watcher ?

[tanema]

@whalesalad themekit used fsnotify in the past thank you for your research. We moved onto a polling mechanism because it could be more reliable cross-platform and less likely to hit file descriptor limits on macOS.

This performance issue is not seemingly widespread, however, and CPU usage spikes are in the minority. I often run themekit all day and it does not run over 5% cpu. There is some tuning that may need to be done because I know that the faster I loop the more CPU this uses, but the slower I poll for events the slower themekit reacts to events. It is a balance of making this work reliably for everyone, managing cpu use, and making themekit responsive.

Lastly, to clear up any misunderstandings, you do not need to ingnore your node_modules folder. Themes in shopify only have a determined set of directories so themekit only watches those. Anything outside of those is not touched. The ignore config is commonly for ignoring config files in the config directory so that they are not accidentally changed

[whalesalad]

I often run themekit all day and it does not run over 5% cpu.

Very very interesting to see such a stark difference in our experiences.

How can I help debug? Is there something I can turn on to emit more telemetry during use? I was very surprised to see OS X reporting that 2 million syscall number after only ~30 seconds of operation. That is over 66k calls per second.

[tanema]

Yes how many files do you have in your theme? The current poll interval is half a second. I believe the main thing it is doing is stating the file but there may be other things. I am also maintaining a list of file checksums to ensure we are not updating a file without reason but that means reading the files when needed as well. Is your theme particularly large? Do you possibly have another tool that is touching all of these files but themekit is not updating them because the checksum has not changed? Do you have another tool that is constantly running along side themekit?

[whalesalad]

To my knowledge I do not have any other processes watching this directory.

There are 273 files in the directory, ignoring node_modules, here is the output of that actually if it helps:

.
├── README.md
├── assets
│   ├── 1-no-filter.4270cd8.png
│   ├── 2-polaroid.111940e.png
│   ├── 3-grayscale.c85c045.png
│   ├── 4-sepia.35ab3f2.png
│   ├── 5-vintage.a337338.png
│   ├── 6-kodachrome.3918134.png
│   ├── 7-technicolor.d43a0a5.png
│   ├── FontAwesome.otf
│   ├── MaterialIcons-Regular.012cf6a.woff
│   ├── MaterialIcons-Regular.570eb83.woff2
│   ├── MaterialIcons-Regular.a37b0c0.ttf
│   ├── MaterialIcons-Regular.e79bfd8.eot
│   ├── ajax-cart.js.liquid
│   ├── app.0db9d4ec1f27923f38c45a07acc4a9df.css
│   ├── app.0db9d4ec1f27923f38c45a07acc4a9df.css.map
│   ├── app.109ba5f5bc11bcab4611.js
│   ├── app.109ba5f5bc11bcab4611.js.map
│   ├── app.333845b73793bea950a8.js
│   ├── app.3a64906fecfc54eeee9b.js
│   ├── app.40d57543e4a0cd2b8d70.js
│   ├── app.427de103fbb5cb7e110e.js
│   ├── app.44f2dc989b3a1ba3b1278d88f9a6f692.css
│   ├── app.47aa6ad109b75d6e8bc4.js
│   ├── app.4d9ed69528c54968598134db6172cf25.css
│   ├── app.50636f0d984671600f623a65e98b4660.css
│   ├── app.6e48781a740e71eceb80.js
│   ├── app.840052506cce2d3239f7.js
│   ├── app.864f7f3f12c6c290dd6f.js
│   ├── app.864f7f3f12c6c290dd6f.js.map
│   ├── app.89e2e444ce8fb4614e90.js
│   ├── app.98f45721a211e37b568b.js
│   ├── app.c1b448afa351022da2ea12fea7198e4d.css
│   ├── app.cfc55e6e54f18e2ed412.js
│   ├── app.dd69a1fe0246d53860ed.js
│   ├── app.deb60afaecd662594c6cf7f665bb0c5d.css
│   ├── app.deb60afaecd662594c6cf7f665bb0c5d.css.map
│   ├── app.f2366f4b4ebc1f5e8e39.js
│   ├── app.f4ae627f392af77fb339.js
│   ├── app.f52065953c1d0d2920b590bd5289a5ca.css
│   ├── app.fe5acacc81cb0a93adbb59f3d26d36de.css
│   ├── circular-black.0637f8a.woff
│   ├── circular-black.0a44f42.eot
│   ├── circular-black.5ddff65.ttf
│   ├── circular-blackitalic.67f978f.eot
│   ├── circular-blackitalic.68725b4.ttf
│   ├── circular-blackitalic.f3365c7.woff
│   ├── circular-bold.7ebfd13.eot
│   ├── circular-bold.a5811b7.woff
│   ├── circular-bold.fc45c93.ttf
│   ├── circular-bolditalic.21dc7c6.woff
│   ├── circular-bolditalic.289de4b.ttf
│   ├── circular-bolditalic.9ff8ed2.eot
│   ├── circular-book.0b4d2d2.woff
│   ├── circular-book.1f6e1b9.ttf
│   ├── circular-book.aa42947.eot
│   ├── circular-medium.12c4b42.eot
│   ├── circular-medium.3900fca.ttf
│   ├── circular-medium.b839115.woff
│   ├── circular-mediumitalic.61ff889.woff
│   ├── circular-mediumitalic.aaae873.eot
│   ├── circular-mediumitalic.c423f01.ttf
│   ├── close.png
│   ├── custom.js.liquid
│   ├── element-icons.535877f.woff
│   ├── element-icons.732389d.ttf
│   ├── fa-brands-400.eot
│   ├── fa-brands-400.svg
│   ├── fa-brands-400.ttf
│   ├── fa-brands-400.woff
│   ├── fa-brands-400.woff2
│   ├── fa-regular-400.eot
│   ├── fa-regular-400.svg
│   ├── fa-regular-400.ttf
│   ├── fa-regular-400.woff
│   ├── fa-regular-400.woff2
│   ├── fa-solid-900.eot
│   ├── fa-solid-900.svg
│   ├── fa-solid-900.ttf
│   ├── fa-solid-900.woff
│   ├── fa-solid-900.woff2
│   ├── fancybox_loading.gif
│   ├── fancybox_loading_2x.gif
│   ├── fancybox_overlay.png
│   ├── fancybox_sprite.png
│   ├── fancybox_sprite_2x.png
│   ├── fastclick.min.js
│   ├── fontawesome-webfont.eot
│   ├── fontawesome-webfont.svg
│   ├── fontawesome-webfont.ttf
│   ├── fontawesome-webfont.woff
│   ├── fontawesome-webfont.woff2
│   ├── gift-card.scss.liquid
│   ├── handlebars.min.js
│   ├── ico-select.svg.liquid
│   ├── icons.eot
│   ├── icons.json
│   ├── icons.svg
│   ├── icons.ttf
│   ├── icons.woff
│   ├── jquery-3.3.1.min.js
│   ├── jquery.currencies.min.js
│   ├── manifest.ccbad715795a8d4b479b.js
│   ├── manifest.ccbad715795a8d4b479b.js.map
│   ├── modernizr.min.js
│   ├── open-iconic.3cf9783.woff
│   ├── open-iconic.47151e8.eot
│   ├── open-iconic.93cc7aa.ttf
│   ├── password.scss.liquid
│   ├── plugins.css.liquid
│   ├── plugins.js
│   ├── respond-proxy.html
│   ├── respond.min.js
│   ├── scripts.js
│   ├── scripts.js.map
│   ├── slider-arrows.png
│   ├── soldout.png
│   ├── timber.js.liquid
│   ├── timber.scss.liquid
│   ├── uncommon.scss.liquid
│   ├── vendor-scripts.2f17f6ca4dbfcd0edb93.js
│   ├── vendor-scripts.577fbfee20e7b7bcf969.js
│   ├── vendor-scripts.784eafc5f39f9d667d55.js
│   ├── vendor-scripts.7b85d409b9ccdd0f541a.js
│   ├── vendor-scripts.8400cc1fc0147d15983a.js
│   ├── vendor-scripts.e07f4f02cf3f067d2ae3.js
│   └── vendor-scripts.e07f4f02cf3f067d2ae3.js.map
├── config
│   ├── settings_data.json
│   └── settings_schema.json
├── config.yml
├── layout
│   ├── password.liquid
│   └── theme.liquid
├── locales
│   ├── de.json
│   ├── en.default.json
│   ├── es.json
│   ├── fr.json
│   └── pt-PT.json
├── package-lock.json
├── package.json
├── scripts
│   └── scripts.js
├── sections
│   ├── announcement-bar.liquid
│   ├── article-template.liquid
│   ├── blog-template.liquid
│   ├── cart-template.liquid
│   ├── collection-list.liquid
│   ├── collection-template.liquid
│   ├── custom-html.liquid
│   ├── feature-row.liquid
│   ├── featured-blog.liquid
│   ├── featured-products.liquid
│   ├── footer-instagram.liquid
│   ├── footer-newsletter.liquid
│   ├── footer.liquid
│   ├── header.liquid
│   ├── home-hero.liquid
│   ├── image-bar.liquid
│   ├── image-with-text-overlay.liquid
│   ├── indiv-product.liquid
│   ├── instagram.liquid
│   ├── list-collections-template.liquid
│   ├── logo-bar.liquid
│   ├── map.liquid
│   ├── newsletter.liquid
│   ├── password-template.liquid
│   ├── product-template.liquid
│   ├── products-block.liquid
│   ├── rich-text.liquid
│   ├── slideshow.liquid
│   ├── testimonials.liquid
│   ├── text-adverts.liquid
│   └── video.liquid
├── snippets
│   ├── ajax-cart-template.liquid
│   ├── breadcrumb.liquid
│   ├── collection-sort-by.liquid
│   ├── currencies.liquid
│   ├── customizer_asset_paths.liquid
│   ├── font-links.liquid
│   ├── grid-view-item-no-match.liquid
│   ├── grid-view-item.liquid
│   ├── icon-amazon_payments.liquid
│   ├── icon-american_express.liquid
│   ├── icon-apple_pay.liquid
│   ├── icon-bitcoin.liquid
│   ├── icon-cirrus.liquid
│   ├── icon-dankort.liquid
│   ├── icon-diners_club.liquid
│   ├── icon-discover.liquid
│   ├── icon-dogecoin.liquid
│   ├── icon-dwolla.liquid
│   ├── icon-forbrugsforeningen.liquid
│   ├── icon-interac.liquid
│   ├── icon-jcb.liquid
│   ├── icon-litecoin.liquid
│   ├── icon-maestro.liquid
│   ├── icon-master.liquid
│   ├── icon-paypal.liquid
│   ├── icon-stripe.liquid
│   ├── icon-visa.liquid
│   ├── live-search-result.liquid
│   ├── mega-menu.liquid
│   ├── mobile-search-bar.liquid
│   ├── oldIE-js.liquid
│   ├── pagination.liquid
│   ├── popup.liquid
│   ├── product-grid-item-price.liquid
│   ├── product-grid-item.liquid
│   ├── related-products.liquid
│   ├── respond.liquid
│   ├── responsive-background-image.liquid
│   ├── responsive-image.liquid
│   ├── search-bar.liquid
│   ├── site-nav--mega-menu.liquid
│   ├── site-nav.liquid
│   ├── social-icons.liquid
│   ├── social-meta-tags.liquid
│   └── swatch.liquid
└── templates
    ├── 404.liquid
    ├── article.liquid
    ├── blog.liquid
    ├── cart.liquid
    ├── collection.liquid
    ├── customers
    │   ├── account.liquid
    │   ├── activate_account.liquid
    │   ├── addresses.liquid
    │   ├── login.liquid
    │   ├── order.liquid
    │   ├── register.liquid
    │   └── reset_password.liquid
    ├── gift_card.liquid
    ├── index.liquid
    ├── list-collections.liquid
    ├── page.contact.liquid
    ├── page.liquid
    ├── password.liquid
    ├── product.liquid
    ├── search.json.liquid
    └── search.liquid

9 directories, 237 files

[HauntedSmores]

Can confirm on windows using WSL. All other commands are fine, but theme watch keeps my CPU at 35% and there's a large startup delay (~30 sec). I have an i5 6600k.

Rolling back to 1.0.0 worked for me. theme update --version=1.0.0

[tanema]

@HauntedSmores which version were you on before? Did you try v1.0.3 there were some performance tunings in 1.02? I specifically moved away from fsnotify because it was broken for windows systems. I will try updating that library as there have been a couple of releases since I added it to this project. Plus I will try to tune the polling interval to try and reduce usage as well.

edit: I have noticed the startup delay while testing on windows as well and I have no idea what it is. All of my go programs that I test on windows have a delay while starting up.

[samueltlg]

Can confirm on windows using WSL. All other commands are fine, but theme watch keeps my CPU at 35% and there's a large startup delay (~30 sec). I have an i5 6600k.

Rolling back to 1.0.0 worked for me. theme update --version=1.0.0

Wow, this fixes everything for me too. Startup time is very quick, rather than 30ish seconds, and CPU is now remaining at 1-2%; should have tried this before!

[HauntedSmores]

@tanema Not sure what I was at before this all happened, but I upgraded to latest which was 1.0.3 and gave me this issue. Then I just tried 1.0.0 on a whim and havnt changed since its been working for me. Also, not sure how relevant this is but, I havn't noticed any other terminal/cli tools having issues. Parcel and rollup watch commands work just fine.

[tanema]

Interesting, if 1.0.0 works well for you then it is not the watching backend because that was introduced in 1.0.0 so I will try to examine additions since then. Thanks for the info

[sinak]

I just tested this and can confirm that switching back to version 1.0.0 reduces CPU usage on OS X from 40% to 1%. 1.0.1, 1.0.2, 1.0.3 all use 40%+ CPU.

[jpagan]

I can also confirm that 1.0.0 doesn't have slow startup or high CPU usage during watch, as opposed to 1.0.3. Windows 10 x64.

[dsuriano]

Just chiming in with similar results (macOS High Sierra 10.13.6) switching from ThemeKit v1.0.3 to v1.0.0 reduces theme watch CPU usage from a constant 40% - 50% to 0.7% - 1.0%.

[mietzz]

Same here. With v1.0.3 it takes a long time to start on Windows 10. Also it takes way longer to process and update the same than with v1.0.0. The longer you keep theme watch open the longer it takes to upload the files. With v1.0.3 my cpu usage is way over 70% all the time. I have an i5-3570k and 16 gb ram.
I now downgraded to v1.0.0 and it works way better.

[petrkrulis]

theme watch on Macbook pro (Catalina)
v1.0.3 - 60 % CPU constantly
v1.0.0 - 1 % CPU constantly

[alexandre-tobia]

Same problem here. any idea @tanema ?

[jeffreyhshapiro]

Themekit v1.0.3
MacBook Pro, Mojave 10.14.6

theme watch 100% CPU usage

[dmkishi]

Yeah, just upgraded ThemeKit and suddenly seeing 50%+ CPU usage all the time....

ThemeKit 1.1.1 darwin/amd64
MacBook Air (11-inch, Early 2015)
2.2 GHz Intel Core i7
8 GB 1600 MHz DDR3
macOS 10.14.6

[tomaszbujnowicz]

The same issue here. ~ 50% CPU usage using "theme watch" command
ThemeKit 1.1.2
Macbook Pro macOS Catalina
node_modules folder is included in my root folder.
when removed, CPU usage is normal which means node_modules is the problem here.

I had to downgrade to 1.0.0 and now it's okay.

[tanema]

node_modules folder is included in my root folder.
when removed, CPU usage is normal which means node_modules is the problem here.

This is a pretty good insight, I will look into this. Currently the watcher just watches the root directory and filters events based on project folders. This was done because some times you will start theme watch without one of the directories and add it later, and it will not be watched by themekit. I think I can fix this.

[adrianocr]

I too am suffering from the theme watch issue on my MBP and 55%+ CPU usage

And if I remove node_modules from the project it does seem that the situation resolves itself.

[tanema]

okay! Give it a try theme update --version=v1.1.5-issue664 and let me know if theme watch is still killing your CPU

[adrianocr]

@tanema might be too early to say it is for sure fixed, but it does seem to me like it might be! 3.3% CPU usage now.

However it does seem like something you did may have messed with themekit's ability to find the assets dir? Got this error:

[development] error loading /Users/adriano/Documents/Projects/xxxxxxxxxxxxxxxxx/assets: readAsset: open /Users/adriano/Documents/Projects/xxxxxxxxxxxxxxxxx/Users/adriano/Documents/Projects/xxxxxxxxxxxxxxxxx/assets: no such file or directory

[tanema]

@adrianocr I do not get this error while running watch so I will need more information.

• When did you get that error? Startup? During runtime?
• Do you have any custom config like a directory setting?
• What OS are you using
• Do events in that directory still work?

[mknpcz]

Hi @tanema I had the same issue with cpu usage on intel i5 Catalina and this patch --version=v1.1.5-issue664 resolved it for me. Thanks!

[adrianocr]

@tanema sorry, seemed to be related to this one project. Can't reproduce the issue any longer.

[maddinq]

okay! Give it a try theme update --version=v1.1.5-issue664 and let me know if theme watch is still killing your CPU

helped me a lot... 1.1.5 works much better than 1.1.4 for me (MacOS Mojave)

[m-allanson]

Thank you for this fix! It made a big difference, dropping from ~30% cpu usage down to ~1%. Running macOS Big Sur.