search

TIM-JYU / TIM

TIM (The Interactive Material) is an open-source cloud-based platform for creating interactive learning documents.
https://tim.education/view/about/en-US
MIT License
13 stars 4 forks source link

Ohj1 sivun haku hidasta vesal tunnuksella #1293

Closed dezhidki closed 2 years ago

dezhidki commented 5 years ago

In GitLab by @vesal on Dec 19, 2018, 14:55

Jollakin muulla tunnuksella sivun luominen kestä 5 sek, vesal tunnuksella 13 sek.

dezhidki commented 5 years ago

In GitLab by @Smibu on Jan 7, 2019, 14:28

Profilointi näyttää:

PATH: '/view/1'
         10723816 function calls (10252487 primitive calls) in 15.593 seconds

   Ordered by: cumulative time
   List reduced from 3665 to 100 due to restriction <100>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   15.631   15.631 /usr/local/lib/python3.6/dist-packages/werkzeug/contrib/profiler.py:95(runapp)
        1    0.000    0.000   15.630   15.630 /service/timApp/util/flask/ReverseProxied.py:22(__call__)
        1    0.000    0.000   15.630   15.630 /usr/local/lib/python3.6/dist-packages/flask/app.py:2262(wsgi_app)
        1    0.000    0.000   15.622   15.622 /usr/local/lib/python3.6/dist-packages/flask/app.py:1801(full_dispatch_request)
        1    0.000    0.000   15.616   15.616 /usr/local/lib/python3.6/dist-packages/flask/app.py:1779(dispatch_request)
        1    0.000    0.000   15.616   15.616 /service/timApp/item/routes.py:82(view_document)
        1    0.001    0.001   15.616   15.616 /service/timApp/item/routes.py:182(view)
        1    0.000    0.000    9.672    9.672 /usr/local/lib/python3.6/dist-packages/flask/templating.py:122(render_template)
24365/6941    0.028    0.000    9.574    0.001 {method 'join' of 'str' objects}
       12    0.000    0.000    9.561    0.797 /usr/local/lib/python3.6/dist-packages/jinja2/asyncsupport.py:74(render)
       12    0.000    0.000    9.560    0.797 /usr/local/lib/python3.6/dist-packages/jinja2/environment.py:993(render)
        1    0.000    0.000    9.560    9.560 /usr/local/lib/python3.6/dist-packages/flask/templating.py:113(_render)
    30407    0.009    0.000    9.550    0.000 /service/timApp/templates/view_html.html:5(root)
    30407    0.008    0.000    9.532    0.000 /service/timApp/templates/document.html:5(root)
    30407    0.008    0.000    9.516    0.000 /service/timApp/templates/item.html:5(root)
    30407    0.009    0.000    9.453    0.000 /service/timApp/templates/base.html:5(root)
    30390    0.009    0.000    9.422    0.000 /service/timApp/templates/base.html:215(block_body)
    30358    0.011    0.000    9.411    0.000 /service/timApp/templates/view_html.html:215(block_content)
    30350    0.123    0.000    9.338    0.000 /service/timApp/templates/partials/paragraphs.html:5(root)
    82900    0.072    0.000    8.854    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/attributes.py:234(__get__)
16713/16690    0.040    0.000    8.836    0.001 /usr/local/lib/python3.6/dist-packages/jinja2/runtime.py:234(call)
9152/9141    0.030    0.000    8.784    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/attributes.py:579(get)
     7286    0.035    0.000    8.742    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/state.py:602(_load_expired)
     2342    0.003    0.000    8.685    0.004 /service/timApp/readmark/readmarkcollection.py:15(class_str)
    11858    0.009    0.000    8.674    0.001 /service/timApp/readmark/readmarkcollection.py:18(yield_classes)
     7286    0.064    0.000    8.671    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:804(load_scalar_attributes)
     9516    0.023    0.000    8.665    0.001 /service/timApp/readmark/readmarkcollection.py:20(<genexpr>)
     7289    0.076    0.000    8.287    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:192(load_on_pk_identity)
     7286    0.018    0.000    8.251    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:173(load_on_ident)
     7289    0.008    0.000    8.159    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:2935(one)
     7289    0.085    0.000    8.151    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:2901(one_or_none)
     7304    0.017    0.000    7.688    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:2990(__iter__)
     7307    0.036    0.000    6.616    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:3012(_execute_and_instances)
     7310    0.012    0.000    5.704    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:882(execute)
     7307    0.011    0.000    5.687    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py:267(_execute_on_connection)
     7307    0.063    0.000    5.676    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:1016(_execute_clauseelement)
        1    0.036    0.036    4.150    4.150 /service/timApp/document/post_process.py:32(post_process_pars)
        1    0.027    0.027    3.474    3.474 /service/timApp/plugin/pluginControl.py:60(pluginify)
     7310    0.098    0.000    3.330    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:1111(_execute_context)
       41    0.001    0.000    2.523    0.062 /usr/local/lib/python3.6/dist-packages/requests/api.py:16(request)
       41    0.001    0.000    2.500    0.061 /usr/local/lib/python3.6/dist-packages/requests/sessions.py:457(request)
    46/41    0.002    0.000    2.434    0.059 /usr/local/lib/python3.6/dist-packages/requests/sessions.py:608(send)
     7312    0.008    0.000    2.373    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py:508(do_execute)
     7314    2.248    0.000    2.369    0.000 {method 'execute' of 'psycopg2.extensions.cursor' objects}
     7309    0.019    0.000    2.268    0.000 <string>:1(<lambda>)
     7309    0.023    0.000    2.249    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py:379(compile)
       27    0.001    0.000    2.243    0.083 /service/timApp/plugin/containerLink.py:88(call_plugin_generic)
     7309    0.017    0.000    2.226    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py:444(_compiler)
     7309    0.060    0.000    2.209    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/compiler.py:393(__init__)
      210    0.001    0.000    2.173    0.010 /usr/lib/python3.6/socket.py:572(readinto)
     7309    0.028    0.000    2.137    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/compiler.py:180(__init__)
7316/7309    0.010    0.000    2.109    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/compiler.py:244(process)
140475/7309    0.167    0.000    2.099    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/visitors.py:75(_compiler_dispatch)
7314/7309    0.083    0.000    2.079    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/compiler.py:1727(visit_select)
        9    0.001    0.000    1.581    0.176 /service/timApp/plugin/containerLink.py:211(render_plugin_multi)
    23428    0.096    0.000    1.286    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:32(instances)
      133    0.000    0.000    1.246    0.009 /usr/local/lib/python3.6/dist-packages/requests/models.py:815(content)
  483/407    0.002    0.000    1.246    0.003 {method 'join' of 'bytes' objects}
      206    0.000    0.000    1.244    0.006 /usr/local/lib/python3.6/dist-packages/requests/models.py:746(generate)
      206    0.001    0.000    1.244    0.006 /usr/local/lib/python3.6/dist-packages/urllib3/response.py:473(stream)
      128    0.002    0.000    1.238    0.010 /usr/local/lib/python3.6/dist-packages/urllib3/response.py:404(read)
      209    1.231    0.006    1.233    0.006 /usr/local/lib/python3.6/dist-packages/gevent/_socket3.py:426(recv_into)
      128    0.001    0.000    1.231    0.010 /usr/lib/python3.6/http/client.py:438(read)
      128    0.001    0.000    1.230    0.010 /usr/lib/python3.6/http/client.py:470(readinto)
      128    0.001    0.000    1.227    0.010 {method 'readinto' of '_io.BufferedReader' objects}
     7314    0.042    0.000    1.175    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/compiler.py:1797(<listcomp>)
       46    0.001    0.000    1.156    0.025 /usr/local/lib/python3.6/dist-packages/requests/adapters.py:394(send)
    51572    0.181    0.000    1.134    0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/compiler.py:1499(_label_select_column)

ja tuosta kiinnostavia ovat rivit

9152/9141    0.030    0.000    8.784    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/attributes.py:579(get)
     7286    0.035    0.000    8.742    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/state.py:602(_load_expired)
     2342    0.003    0.000    8.685    0.004 /service/timApp/readmark/readmarkcollection.py:15(class_str)
    11858    0.009    0.000    8.674    0.001 /service/timApp/readmark/readmarkcollection.py:18(yield_classes)
     7286    0.064    0.000    8.671    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:804(load_scalar_attributes)
     9516    0.023    0.000    8.665    0.001 /service/timApp/readmark/readmarkcollection.py:20(<genexpr>)
     7289    0.076    0.000    8.287    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:192(load_on_pk_identity)
     7286    0.018    0.000    8.251    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:173(load_on_ident)
     7289    0.008    0.000    8.159    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:2935(one)
     7289    0.085    0.000    8.151    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:2901(one_or_none)
     7304    0.017    0.000    7.688    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:2990(__iter__)
     7307    0.036    0.000    6.616    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:3012(_execute_and_instances)
     7310    0.012    0.000    5.704    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:882(execute)
     7307    0.011    0.000    5.687    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py:267(_execute_on_connection)
     7307    0.063    0.000    5.676    0.001 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:1016(_execute_clauseelement)

eli jostain syystä ikään kuin jokainen lukumerkintä aiheuttaa tietokantahaun, vaikka lukumerkinnät ladataan yhdellä kyselyllä.

Debuggauksen perusteella lukumerkinnän type-attribuutin lukeminen aiheuttaa tuon kyselyn. Tutkin vielä, miksi niin käy.

dezhidki commented 5 years ago

In GitLab by @Smibu on Jan 7, 2019, 19:13

Vika korjattu stack-haaraan. Vika oli, että pyynnön aikana tehtiin commit, joka expiroi kaikki sqlalchemy-oliot, jolloin kunkin lukumerkintäolion attribuutit haettiin uudestaan kannasta. Jos lukumerkintöjä oli paljon, niin tuo hidastui paljon.

Esim. https://timdevs5.it.jyu.fi/view/1 on nyt vesal-tunnarillakin 5 sek luokkaa. Päivitin betalle myös.

dezhidki commented 5 years ago

In GitLab by @vesal on Jan 7, 2019, 19:43

Esim. https://timdevs5.it.jyu.fi/view/1 on nyt vesal-tunnarillakin 5 sek luokkaa. Päivitin betalle myös.

Hyvä :-)

betassa näköjään 4 sek luokkaa. Nyt niitä paljon lukumerkinnän juttuja voi ruveta tuleman kun painotin luennolla että klikatkaa ne punaiset pois rattaan takaa.

DOM content on kuitenkin liki 9 sek, eli tuolla JS päässä on aikojen saatossa tapahtunut paljon hidastumista kun koko moniste tuli joskus huonommassa koneessa alle 5 sek. Nyt RUSTilla tuosta voi leikata 3 sek pois (???). Tosin hyvä puoli sitten on se, että palvelimen kapasitettitarvetta saa tuolla pudotettu aika paljon ja loppu jää selaimen murheeksi.

Tosin työpaikalla DOM content näyttäisi olevan 6.25 sek, eli mulla kotono n. 3 sek menee hitaan bingin takia, eli jokainen uusi pyyntö lisääntyy vähintään bingin verran ja niitä pyyntöjä tulee paljon. Yksi pieni stylesheet voi olla 180 ms kun se työpaikan koneella on 45 ms. video.png 45 ms vs 8 ms jne.

Eli varmaan jos mun kotikonetta haluaisi optimoida, niin kannattaisi cacheta html:ään image-tagin sisään se kuva data urlina ja lähettää kaikki css:ät yhtenä kasana. Tosin näyttäisi että nyktkin tuo n. 8 asiaa lataa yhtäaikaa.

KOtikoneella on n. 2 sek tauko 6.2 sek ja 7.8 sek välillä jolloin ei oe mitään verkkoliikennettä. Työkoneella (jossa ehkä 50% parempi prossu) on tauko 4.8 ja vajaa 6 sek välillä. Saako muuten noita Chromella aikapalkkista maalattuja aikoja lukuina mistään?

Vesa

dezhidki commented 5 years ago

In GitLab by @Smibu on Jan 14, 2019, 09:22

Saako muuten noita Chromella aikapalkkista maalattuja aikoja lukuina mistään?

En ainakaan löytänyt äkkiseltään mitään.

dezhidki commented 5 years ago

In GitLab by @Smibu on Jan 14, 2019, 09:22

closed