After last update: Python daemon at 99% CPU, running bench start, new-site etc

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

Works okay for me. All our systems are on develop and they seem to be working fine too!

it seems to be ok after last fix:

please close the post

thx