Hi there,
after last frappe update, the VM is using more than 90% of CPU on:
bench new-site [site-name]
and taking ages to create a new site and installing apps
top - 20:35:54 up 30 min, 2 users, load average: 1,29, 1,00, 0,65
Tasks: 93 total, 2 running, 91 sleeping, 0 stopped, 0 zombie
%Cpu(s): 92,7 us, 4,5 sy, 0,0 ni, 1,1 id, 0,0 wa, 0,0 hi, 1,1 si, 0,0 st
KiB Mem : 2609172 total, 244504 free, 436600 used, 1928068 buff/cache
KiB Swap: 839676 total, 839676 free, 0 used. 1971896 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26351 frappe 20 0 463352 200880 5768 S 92,7 7,7 4:50.76 python
25030 mysql 20 0 777940 140568 11900 S 5,0 5,4 0:16.01 mysqld
11 root 20 0 0 0 0 R 0,7 0,0 0:02.33 rcuos/0
10 root 20 0 0 0 0 S 0,3 0,0 0:00.99 rcu_sched
26372 root 20 0 0 0 0 S 0,3 0,0 0:00.12 kworker/0:2
1 root 20 0 41200 3640 2404 S 0,0 0,1 0:00.88 systemd
2 root 20 0 0 0 0 S 0,0 0,0 0:00.00 kthreadd
3 root 20 0 0 0 0 S 0,0 0,0 0:00.37 ksoftirqd/0
6 root 20 0 0 0 0 S 0,0 0,0 0:00.00 kworker/u2:0
7 root rt 0 0 0 0 S 0,0 0,0 0:00.00 migration/0
8 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcu_bh
9 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/0
12 root rt 0 0 0 0 S 0,0 0,0 0:00.01 watchdog/0
13 root 0 -20 0 0 0 S 0,0 0,0 0:00.00 khelper
14 root 20 0 0 0 0 S 0,0 0,0 0:00.00 kdevtmpfs
15 root 0 -20 0 0 0 S 0,0 0,0 0:00.00 netns
16 root 0 -20 0 0 0 S 0,0 0,0 0:00.00 perf
17 root 0 -20 0 0 0 S 0,0 0,0 0:00.00 writeback
Update:
same problem on bench start, CPU at 99% and werkzeug keep detecting changes, some examples:
21:57:54 web.1 | * Debugger is active!
21:57:54 web.1 | * Debugger pin code: 213-621-543
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/hooks.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/hooks.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/hooks.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/hooks.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/jobtaskscheduler/jobtaskscheduler/hooks.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/jobtaskscheduler/jobtaskscheduler/hooks.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/jobtaskscheduler/jobtaskscheduler/hooks.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/jobtaskscheduler/jobtaskscheduler/hooks.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/istorecast_ceu/istorecast_ceu/hooks.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/istorecast_ceu/istorecast_ceu/hooks.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/istorecast_ceu/istorecast_ceu/hooks.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/istorecast_ceu/istorecast_ceu/hooks.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/autodoc.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/autodoc.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/autodoc.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/autodoc.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/__init__.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/__init__.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/__init__.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/__init__.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/print.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/print.py', reloading
21:58:03 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/print.py', reloading
21:58:03 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/print.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/login.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/login.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/login.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/www/login.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/oauth.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/oauth.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/oauth.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/oauth.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/ldap_settings.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/ldap_settings.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/ldap_settings.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/ldap_settings/ldap_settings.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/__init__.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/__init__.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/social_login_keys.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/social_login_keys.py', reloading
21:58:06 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/social_login_keys.py', reloading
21:58:06 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/integrations/doctype/social_login_keys/social_login_keys.py', reloading
21:58:10 web.1 | 10.0.2.2 - - [18/Nov/2016 21:58:10] "GET / HTTP/1.1" 200 -
21:58:10 web.1 | INFO:werkzeug:10.0.2.2 - - [18/Nov/2016 21:58:10] "GET / HTTP/1.1" 200 -
21:58:10 web.1 | Exception in thread Thread-2 (most likely raised during interpreter shutdown):Exception in thread Thread-1 (most likely raised during interpreter shutdown):
21:58:10 web.1 | Traceback (most recent call last):
21:58:10 web.1 | File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
21:58:10 web.1 | Traceback (most recent call last):
21:58:10 web.1 | File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
21:58:10 web.1 | File "/usr/lib/python2.7/threading.py", line 754, in run
21:58:10 web.1 | File "/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/werkzeug/serving.py", line 659, in inner
21:58:10 web.1 | File "/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/werkzeug/serving.py", line 499, in serve_forever
21:58:10 web.1 | File "/usr/lib/python2.7/SocketServer.py", line 233, in serve_forever
21:58:10 web.1 | File "/usr/lib/python2.7/SocketServer.py", line 292, in _handle_request_noblock
21:58:10 web.1 | File "/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/werkzeug/serving.py", line 508, in handle_error
21:58:10 web.1 | <type 'exceptions.AttributeError'>: 'NoneType' object has no attribute 'handle_error'
21:58:10 web.1 |
21:58:10 web.1 | File "/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/watchdog/observers/api.py", line 236, in run
21:58:10 web.1 | File "/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/watchdog/observers/api.py", line 401, in dispatch_events
21:58:10 web.1 | File "/usr/lib/python2.7/Queue.py", line 177, in get
21:58:10 web.1 | File "/usr/lib/python2.7/threading.py", line 355, in wait
21:58:10 web.1 | <type 'exceptions.TypeError'>: 'NoneType' object is not callable
21:58:10 web.1 | * Restarting with inotify reloader
21:58:10 web.1 | * Debugger is active!
21:58:10 web.1 | * Debugger pin code: 213-621-543
21:58:10 web.1 | 10.0.2.2 - - [18/Nov/2016 21:58:10] "GET /assets/js/frappe-web.min.js HTTP/1.1" 200 -
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page/__init__.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page/__init__.py', reloading
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page/page.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page/page.py', reloading
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page/page.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page/page.py', reloading
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/__init__.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/__init__.py', reloading
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/__init__.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/__init__.py', reloading
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/page_role.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/page_role.py', reloading
21:59:33 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/page_role.py', reloading
21:59:33 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/core/doctype/page_role/page_role.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/momentjs.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/momentjs.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/momentjs.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/utils/momentjs.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/__init__.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/__init__.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/__init__.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/__init__.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/__init__.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/__init__.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/__init__.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/__init__.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/__init__.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/__init__.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/__init__.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/__init__.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/print_settings.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/print_settings.py', reloading
21:59:34 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/print_settings.py', reloading
21:59:34 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/print/doctype/print_settings/print_settings.py', reloading
21:59:35 web.1 | Module import failed for Page (frappe.core.doctype.page.page_dashboard)
21:59:45 rqscheduler.1 | 21:59:45 Checking for scheduled jobs...
21:59:52 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/__init__.py', reloading
21:59:52 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/__init__.py', reloading
21:59:52 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/__init__.py', reloading
21:59:52 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/__init__.py', reloading
21:59:52 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/todo.py', reloading
21:59:52 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/todo.py', reloading
21:59:52 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/todo.py', reloading
21:59:52 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/todo/todo.py', reloading
21:59:53 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/__init__.py', reloading
21:59:53 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/__init__.py', reloading
21:59:53 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/__init__.py', reloading
21:59:53 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/__init__.py', reloading
21:59:53 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/event.py', reloading
21:59:53 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/event.py', reloading
21:59:53 web.1 | * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/event.py', reloading
21:59:53 web.1 | INFO:werkzeug: * Detected change in '/home/frappe/frappe-bench/apps/frappe/frappe/desk/doctype/event/event.py', reloading
...................
22:00:07 web.1 | 10.0.2.2 - - [18/Nov/2016 22:00:07] "GET /desk HTTP/1.1" 200 -
22:00:07 web.1 | INFO:werkzeug:10.0.2.2 - - [18/Nov/2016 22:00:07] "GET /desk HTTP/1.1" 200 -
22:00:07 web.1 | Unhandled exception in thread started by <bound method Thread.__bootstrap of <Thread(Thread-1, stopped daemon 140137731098368)>>
22:00:07 web.1 | Traceback (most recent call last):
22:00:07 web.1 | File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
22:00:07 web.1 | self.__bootstrap_inner()
22:00:07 web.1 | File "/usr/lib/python2.7/threading.py", line 814, in __bootstrap_inner
22:00:07 web.1 | (self.name, _format_exc()))
22:00:07 web.1 | File "/usr/lib/python2.7/traceback.py", line 241, in format_exc
22:00:07 web.1 | etype, value, tb = sys.exc_info()
22:00:07 web.1 | AttributeError: 'NoneType' object has no attribute 'exc_info'
22:00:07 web.1 | * Restarting with inotify reloader
22:00:07 web.1 | * Debugger is active!
22:00:07 web.1 | * Debugger pin code: 213-621-543
Update 2: Creating a new site, it took about 40 mins …that’s not normal at all
frappe@ubuntu16-dev:~/frappe-bench$ date
sab 19 nov 2016, 08.25.23, CET
frappe@ubuntu16-dev:~/frappe-bench$ bench new-site test.dev
MySQL root password:
Installing frappe...
Updating frappe : [========================================]
Updating country info : [========================================]
Set Administrator password:
Re-enter Administrator password:
*** Scheduler is disabled ***
frappe@ubuntu16-dev:~/frappe-bench$ date
sab 19 nov 2016, 09.04.45, CET
Can you please have a look?
Thx