search

django-commons / django-debug-toolbar

A configurable set of panels that display various debug information about the current request/response.
https://django-debug-toolbar.readthedocs.io
BSD 3-Clause "New" or "Revised" License
8.1k stars 1.05k forks source link

Extreme slowdown in staticfiles panel #948

Open tino opened 7 years ago

tino commented 7 years ago

For some reason the staticfiles finder is doing a lot of work, and ends up eating more than two minutes in the process_response method (started profiling at the first line, and stopped before the return):

         2645701 function calls (2516832 primitive calls) in 132.227 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  132.106  132.106 /usr/local/lib/python3.5/dist-packages/debug_toolbar/panels/staticfiles.py:118(generate_stats)
        1    0.197    0.197  132.035  132.035 /usr/local/lib/python3.5/dist-packages/debug_toolbar/panels/staticfiles.py:131(get_staticfiles_finders)
156991/29435    0.185    0.000  130.380    0.004 /usr/local/lib/python3.5/dist-packages/django/contrib/staticfiles/utils.py:21(get_files)
    29294    0.024    0.000  130.073    0.004 /usr/local/lib/python3.5/dist-packages/django/contrib/staticfiles/finders.py:106(list)
     4453    0.349    0.000  130.014    0.029 /usr/local/lib/python3.5/dist-packages/django/core/files/storage.py:394(listdir)
    33909    0.212    0.000  107.386    0.003 /usr/lib/python3.5/genericpath.py:39(isdir)
    33916  107.161    0.003  107.161    0.003 {built-in method posix.stat}
     4453   21.620    0.005   21.620    0.005 {built-in method posix.listdir}
    33887    0.055    0.000    1.629    0.000 /usr/local/lib/python3.5/dist-packages/django/core/files/storage.py:404(path)
    33902    0.236    0.000    1.575    0.000 /usr/local/lib/python3.5/dist-packages/django/utils/_os.py:54(safe_join)
    67844    0.086    0.000    0.848    0.000 /usr/lib/python3.5/posixpath.py:356(abspath)
   101649    0.405    0.000    0.693    0.000 /usr/lib/python3.5/posixpath.py:71(join)
    67846    0.416    0.000    0.628    0.000 /usr/lib/python3.5/posixpath.py:319(normpath)
      135    0.000    0.000    0.340    0.003 /usr/local/lib/python3.5/dist-packages/django/contrib/staticfiles/finders.py:142(list)
   169493    0.140    0.000    0.227    0.000 /usr/lib/python3.5/posixpath.py:39(_get_sep)
    33902    0.183    0.000    0.215    0.000 /usr/local/lib/python3.5/dist-packages/django/utils/_os.py:63(<listcomp>)
   339835    0.142    0.000    0.142    0.000 {method 'startswith' of 'str' objects}
    67844    0.062    0.000    0.134    0.000 /usr/lib/python3.5/posixpath.py:61(isabs)
   327664    0.123    0.000    0.123    0.000 {built-in method builtins.isinstance}
        1    0.000    0.000    0.114    0.114 /usr/local/lib/python3.5/dist-packages/debug_toolbar/toolbar.py:56(render_toolbar)
        1    0.000    0.000    0.114    0.114 /usr/local/lib/python3.5/dist-packages/django/template/loader.py:58(render_to_string)

I must say I am running inside a Docker container, don't know if that matters.

There are 1089 files in our STATIC_ROOT, and a 29142 in STATICFILES_DIRS, node_modules... Would that be the culprit? It almost adds up to the 156991/29435 ncalls (don't know how to interpret the slash here in the pstats output though).

matthiask commented 7 years ago

Wow that's awfully slow. The time is mostly spent in stat and listdir it seems. Maybe filesystems operations are slow inside Docker depending on the environment, but I don't know.

We use node_modules/webpack but node_modules would never be part of STATICFILES_DIRS; may I ask the reason for putting node_modules in there?

tony commented 7 years ago

Removing 'debug_toolbar.panels.staticfiles.StaticFilesPanel', from DEBUG_TOOLBAR_PANELS fixes it for me.

No clue why the performance slowdown is so bad, but it's huge. Talking about 500-600ms a page load, easy.