Optimise queries, particularly exports and detail display of fluoro.

Issue #484 resolved
Ed McDonagh
created an issue

Start by adding https://django-debug-toolbar.readthedocs.io for developer use.

Comments (57)

  1. Ed McDonagh reporter

    Completely unscientific single request for RF detail view of study with 316 events, in debug mode (so slower, but I can see the number of database queries and CPU time:

    branch No. queries time taken (ms) CPU time (ms)
    develop 7,597 15,231 414,500
    issue484... 4,109 2,821 53,436
  2. Ed McDonagh reporter

    Comparison for listing of 4 study RF filtered list:

    branch No. queries time taken (ms) CPU time (ms)
    develop 76 52 836
    issue484optimisefluoro 32 25 364
  3. Ed McDonagh reporter

    Exciting isn't it! Well, I'm finding it exciting!

    I think they could be optimised further if I understood django better, but I'm going for any low hanging fruit I can find and it is making a significant difference I reckon. I tried to improve the table that summarises the dose and times for the fluoro detail page for example, but I got stuck so reverted.

  4. Ed McDonagh reporter

    Merged in issue484optimisefluoro (pull request #136)

    Issue484optimisefluoro

    Refs #484

    Stats from two identical servers with the same PostgreSQL database, both running builtin webserver.

    Times are wait times in seconds, recorded by the browser, and are the mean of three refreshes.

    Page loaded v0.7.4 issue484 branch
    CT Filtered, 150,962 studies, first page of 6,039 6.51 3.39
    CT Detail, study with four events 1.26 1.16
    Fluoro Filtered, 1,335 studies, first page of 67 8.31 4.40
    Fluoro Detail, study with 146 events 55.3 30.6
    Mammo Filtered, 66,051 studies, first page of 1,322 17.4 12.2
    Mammo Detail, study with four events 2.02 1.28
    DX Filtered, 32,462 studies, first page of 650 11.24 4.37
    DX Detail, study with 14 events 8.25 4.17
    DX Detail, study with one event 1.44 1.05

    → <<cset 3885a37f4b61>>

  5. Ed McDonagh reporter

    I'm confused. I've exhausted all query optimisations I can think of, and now have 58 queries for my current dev home page. But the last commit was 40... Also, accidentally did a code reformat, which is unfortunate as it makes comparisons hard. refs #484

    → <<cset 61bfd336f98f>>

  6. Ed McDonagh reporter

    Update on progress (or lack of) for home page rendition. Unfortunately, despite reducing the number of queries from 94 down to 39 on my development environment laptop, when testing with a real (large) database the version with fewer queries takes longer :-(

    Using the database used for the tests of the filtered and detail pages above, I get the following approximate stats. The first three are from the Django Debug Toolbar, the last from Chrome's tools.

    Branch Number of queries SQL time (ms) CPU time (ms) Total? (ms) Chrome Wait (s)
    develop 151 ~ 6400 ~ 2000 ~ 8000 ~ 8
    484 branch 58 ~ 5500 ~ 7000 ~ 11,500 ~ 11.7

    I have been experimenting with adding indexes, and whilst I can shave a second or two off the 484 branch time, I can't get down to the develop times (which are the same as the 0.7.4 times). It seems that in this case doing more queries is cheaper than doing fewer!

    SQL explained
    Executed SQL
    SELECT ••• FROM "remapp_generalstudymoduleattr" INNER JOIN "remapp_generalequipmentmoduleattr" ON ( "remapp_generalstudymoduleattr"."id" = "remapp_generalequipmentmoduleattr"."general_study_module_attributes_id" ) INNER 
    JOIN "remapp_uniqueequipmentnames" ON ( "remapp_generalequipmentmoduleattr"."unique_equipment_name_id" = "remapp_uniqueequipmentnames"."id" ) WHERE ("remapp_generalstudymoduleattr"."modality_type" = 'MG' AND 
    "remapp_uniqueequipmentnames"."display_name" = 'RMH Sutton RDAC 3') ORDER BY "remapp_generalstudymoduleattr"."study_date" DESC, "remapp_generalstudymoduleattr"."study_time" DESC
    Time
    165.947914124 ms
    Database
    default
    QUERY PLAN
    Sort  (cost=14567.08..14572.80 rows=2287 width=360) (actual time=160.022..160.716 rows=11805 loops=1)
      Sort Key: remapp_generalstudymoduleattr.study_date DESC, remapp_generalstudymoduleattr.study_time DESC
      Sort Method: quicksort  Memory: 3468kB
      ->  Nested Loop  (cost=25.12..14439.47 rows=2287 width=360) (actual time=0.354..145.173 rows=11805 loops=1)
            ->  Hash Join  (cost=24.70..9438.28 rows=8780 width=4) (actual time=0.327..100.635 rows=11805 loops=1)
                  Hash Cond: (remapp_generalequipmentmoduleattr.unique_equipment_name_id = remapp_uniqueequipmentnames.id)
                  ->  Seq Scan on remapp_generalequipmentmoduleattr  (cost=0.00..8384.11 rows=251111 width=8) (actual time=0.027..39.684 rows=251111 loops=1)
                  ->  Hash  (cost=24.57..24.57 rows=10 width=4) (actual time=0.265..0.265 rows=10 loops=1)
                        Buckets: 1024  Batches: 1  Memory Usage: 9kB
                        ->  Seq Scan on remapp_uniqueequipmentnames  (cost=0.00..24.57 rows=10 width=4) (actual time=0.034..0.256 rows=10 loops=1)
                              Filter: (display_name = 'RMH Sutton RDAC 3'::text)
                              Rows Removed by Filter: 276
            ->  Index Scan using remapp_general_study_module_attributes_pkey on remapp_generalstudymoduleattr  (cost=0.42..0.56 rows=1 width=360) (actual time=0.003..0.003 rows=1 loops=11805)
                  Index Cond: (id = remapp_generalequipmentmoduleattr.general_study_module_attributes_id)
                  Filter: ((modality_type)::text = 'MG'::text)
    Planning time: 2.037 ms
    Execution time: 161.459 ms
    

    There are obviously some database optimisations to be made, and whilst my knowledge of the database queries is improving, so far I haven't been able to get over the fact that we need to the hash join between the GeneralEquipmentModuleAttr table and the UniqueEquipmentNames table, and then do a sequential scan on the result. With 11,805 rows and 251,111 rows in this example for the join and the scan respectively, that takes 100 ms and 40 ms to plan and execute. For one query of 58, many of which are very similar to this one.

    If anyone understands this stuff better than I do, please shout!

  7. Ed McDonagh reporter

    Quick export test with latest code.

    Branch Number of CT studies Export time
    0.7.4 41, variety of Philips and Siemens 4 minutes and 10 seconds
    develop 41, same studies as above 1 minute and 39 seconds
    issue484optimiseexports 41, same studies as above 49.5 seconds

    Wonderful :-)

  8. Ed McDonagh reporter

    Again for DX.

    Branch Number of DX studies Export time
    0.7.4 59, various 4 minutes and 14 seconds
    develop 59, as above 2 minutes and 3 seconds
    issue484optimiseexports 59, as above 1 minute and 10 seconds
  9. Ed McDonagh reporter

    Again for RF:

    Branch Format Number of studies Export time
    0.7.4 XLSX 7, various 11 minutes and 47 seconds
    develop XLSX 7, as above 9 minutes and 28 seconds
    issue484optimiseexports XLSX 7, as above 4 minutes and 12 seconds
    0.7.4 CSV 56, various 48.3 seconds
    develop CSV 56, as above 42.2 seconds
    issue484optimiseexports CSV 56, as above 29.9 seconds
  10. Ed McDonagh reporter

    And finally some Mammo stats:

    Branch Format Number of studies Export time
    0.7.4 CSV 94 10 minutes and 6 seconds
    develop CSV 94, as above 5 minutes and 38 seconds
    issue484optimiseexports CSV 94, as above 2 minutes and 48 seconds
    issue484optimiseexports XLSX 94, as above 2 minutes and 57 seconds
  11. Log in to comment