Poor performance with 2.5.52, load and process in D state

From: Andrew Morton <[email protected]>

Ok, I'm back with the results of the osdb test against 2.4.19 and 2.5.52 Both the kernel booted with apm=off mem=40M
osdb ran with 40M of data.
To summarize the results:
2.4.19 "Single User Test" 806.78 seconds (0:13:26.78)
2.5.52 "Single User Test" 3771.85 seconds (1:02:51.85)

Something strange is happening here.

Following the full logs of the test

"osdb"
"Invoked: ./bin/osdb-pg --nomulti --logfile /var/lib/pgsql/2.4.19-nomulti-40M.log"

                 create_tables()	0.10 seconds	return value = 0
                          load()	34.59 seconds	return value = 0
     create_idx_uniques_key_bt()	24.31 seconds	return value = 0
     create_idx_updates_key_bt()	26.53 seconds	return value = 0
     create_idx_hundred_key_bt()	22.78 seconds	return value = 0
      create_idx_tenpct_key_bt()	24.08 seconds	return value = 0
 create_idx_tenpct_key_code_bt()	6.03 seconds	return value = 0
        create_idx_tiny_key_bt()	0.33 seconds	return value = 0
      create_idx_tenpct_int_bt()	2.97 seconds	return value = 0
   create_idx_tenpct_signed_bt()	2.44 seconds	return value = 0
     create_idx_uniques_code_h()	13.95 seconds	return value = 0

create_idx_tenpct_double_bt() 3.78 seconds return value = 0
create_idx_updates_decim_bt() 7.74 seconds return value = 0
create_idx_tenpct_float_bt() 2.61 seconds return value = 0
create_idx_updates_int_bt() 4.37 seconds return value = 0
create_idx_tenpct_decim_bt() 4.84 seconds return value = 0
create_idx_hundred_code_h() 7.84 seconds return value = 0
create_idx_tenpct_name_h() 124.83 seconds return value = 0
create_idx_updates_code_h() 11.82 seconds return value = 0
create_idx_tenpct_code_h() 11.95 seconds return value = 0
create_idx_updates_double_bt() 3.99 seconds return value = 0
create_idx_hundred_foreign() 12.27 seconds return value = 0
populateDataBase() 355.06 seconds return value = 0

"Logical database size 40MB"

                      sel_1_cl()	0.24 seconds	return value = 1
                     join_3_cl()	0.10 seconds	return value = 0
                   sel_100_ncl()	0.33 seconds	return value = 100
                    table_scan()	1.81 seconds	return value = 0
                      agg_func()	16.48 seconds	return value = 100
                      agg_scal()	1.51 seconds	return value = 0
                    sel_100_cl()	1.17 seconds	return value = 100
                    join_3_ncl()	14.47 seconds	return value = 1
                 sel_10pct_ncl()	3.16 seconds	return value = 10000
             agg_simple_report()	66.67 seconds	return value = 990009900
            agg_info_retrieval()	0.26 seconds	return value = 0
               agg_create_view()	0.48 seconds	return value = 0
           agg_subtotal_report()	4.81 seconds	return value = 1000
              agg_total_report()	6.33 seconds	return value = 932849
                     join_2_cl()	0.43 seconds	return value = 0
                        join_2()	3.13 seconds	return value = 1000
       sel_variable_select_low()	1.78 seconds	return value = 0
      sel_variable_select_high()	3.25 seconds	return value = 25000
                     join_4_cl()	0.04 seconds	return value = 0
                      proj_100()	19.83 seconds	return value = 10000
                    join_4_ncl()	21.71 seconds	return value = 1
                    proj_10pct()	12.29 seconds	return value = 100000
                     sel_1_ncl()	0.37 seconds	return value = 1
                    join_2_ncl()	6.70 seconds	return value = 1
                integrity_test()	2.27 seconds	return value = 0
             drop_updates_keys()	0.30 seconds	return value = 0
                     bulk_save()	0.16 seconds	return value = 0
                   bulk_modify()	296.61 seconds	return value = 0
          upd_append_duplicate()	0.42 seconds	return value = 0
          upd_remove_duplicate()	0.00 seconds	return value = 0
                 upd_app_t_mid()	0.00 seconds	return value = 1
                 upd_mod_t_mid()	0.30 seconds	return value = 0
                 upd_del_t_mid()	0.30 seconds	return value = 0
                 upd_app_t_end()	0.03 seconds	return value = 1
                 upd_mod_t_end()	0.30 seconds	return value = 0
                 upd_del_t_end()	0.30 seconds	return value = 0
     create_idx_updates_code_h()	12.21 seconds	return value = 0
                 upd_app_t_mid()	0.07 seconds	return value = 1
                 upd_mod_t_cod()	0.03 seconds	return value = 0
                 upd_del_t_mid()	0.67 seconds	return value = 0
     create_idx_updates_int_bt()	3.63 seconds	return value = 0
                 upd_app_t_mid()	0.16 seconds	return value = 1
                 upd_mod_t_int()	0.05 seconds	return value = 0
                 upd_del_t_mid()	0.94 seconds	return value = 0
                   bulk_append()	0.44 seconds	return value = 0
                   bulk_delete()	299.05 seconds	return value = 0

"Single User Test" 806.78 seconds (0:13:26.78)

"osdb"
"Invoked: ./bin/osdb-pg --nomulti --logfile /var/lib/pgsql/2.5.52-nomulti-40M.log"

                 create_tables()	0.06 seconds	return value = 0
                          load()	36.89 seconds	return value = 0
     create_idx_uniques_key_bt()	1043.04 seconds	return value = 0
     create_idx_updates_key_bt()	808.48 seconds	return value = 0
     create_idx_hundred_key_bt()	749.90 seconds	return value = 0
      create_idx_tenpct_key_bt()	641.84 seconds	return value = 0
 create_idx_tenpct_key_code_bt()	6.11 seconds	return value = 0
        create_idx_tiny_key_bt()	0.06 seconds	return value = 0
      create_idx_tenpct_int_bt()	3.35 seconds	return value = 0
   create_idx_tenpct_signed_bt()	3.01 seconds	return value = 0
     create_idx_uniques_code_h()	18.30 seconds	return value = 0

create_idx_tenpct_double_bt() 4.91 seconds return value = 0
create_idx_updates_decim_bt() 7.18 seconds return value = 0
create_idx_tenpct_float_bt() 3.91 seconds return value = 0
create_idx_updates_int_bt() 3.93 seconds return value = 0
create_idx_tenpct_decim_bt() 6.39 seconds return value = 0
create_idx_hundred_code_h() 8.03 seconds return value = 0
create_idx_tenpct_name_h() 130.66 seconds return value = 0
create_idx_updates_code_h() 13.18 seconds return value = 0
create_idx_tenpct_code_h() 12.96 seconds return value = 0
create_idx_updates_double_bt() 4.45 seconds return value = 0
create_idx_hundred_foreign() 11.29 seconds return value = 0
populateDataBase() 3518.83 seconds return value = 0

"Logical database size 40MB"

                      sel_1_cl()	0.28 seconds	return value = 1
                     join_3_cl()	0.11 seconds	return value = 0
                   sel_100_ncl()	2.25 seconds	return value = 100
                    table_scan()	1.80 seconds	return value = 0
                      agg_func()	15.74 seconds	return value = 100
                      agg_scal()	1.66 seconds	return value = 0
                    sel_100_cl()	1.79 seconds	return value = 100
                    join_3_ncl()	23.20 seconds	return value = 1
                 sel_10pct_ncl()	3.57 seconds	return value = 10000
             agg_simple_report()	69.20 seconds	return value = 990009900
            agg_info_retrieval()	0.44 seconds	return value = 0
               agg_create_view()	0.39 seconds	return value = 0
           agg_subtotal_report()	10.68 seconds	return value = 1000
              agg_total_report()	9.65 seconds	return value = 932849
                     join_2_cl()	0.11 seconds	return value = 0
                        join_2()	3.57 seconds	return value = 1000
       sel_variable_select_low()	1.55 seconds	return value = 0
      sel_variable_select_high()	3.81 seconds	return value = 25000
                     join_4_cl()	0.07 seconds	return value = 0
                      proj_100()	21.08 seconds	return value = 10000
                    join_4_ncl()	36.16 seconds	return value = 1
                    proj_10pct()	13.07 seconds	return value = 100000
                     sel_1_ncl()	0.18 seconds	return value = 1
                    join_2_ncl()	12.18 seconds	return value = 1
                integrity_test()	9.07 seconds	return value = 0
             drop_updates_keys()	0.63 seconds	return value = 0
                     bulk_save()	0.69 seconds	return value = 0
                   bulk_modify()	1923.65 seconds	return value = 0
          upd_append_duplicate()	0.30 seconds	return value = 0
          upd_remove_duplicate()	0.09 seconds	return value = 0
                 upd_app_t_mid()	0.03 seconds	return value = 1
                 upd_mod_t_mid()	2.04 seconds	return value = 0
                 upd_del_t_mid()	1.67 seconds	return value = 0
                 upd_app_t_end()	0.08 seconds	return value = 1
                 upd_mod_t_end()	1.67 seconds	return value = 0
                 upd_del_t_end()	1.78 seconds	return value = 0
     create_idx_updates_code_h()	13.74 seconds	return value = 0
                 upd_app_t_mid()	0.12 seconds	return value = 1
                 upd_mod_t_cod()	0.03 seconds	return value = 0
                 upd_del_t_mid()	2.29 seconds	return value = 0
     create_idx_updates_int_bt()	4.06 seconds	return value = 0
                 upd_app_t_mid()	0.15 seconds	return value = 1
                 upd_mod_t_int()	0.01 seconds	return value = 0
                 upd_del_t_mid()	2.13 seconds	return value = 0
                   bulk_append()	2.59 seconds	return value = 0
                   bulk_delete()	1570.86 seconds	return value = 0

"Single User Test" 3771.85 seconds (1:02:51.85)

______________________________________________
http://www.linuxmail.org/
Now with POP3/IMAP access for only US$19.95/yr

Powered by Outblaze

I could reproduce this.

What's happening is that when the test starts up it does a lot of writing which causes 2.4 to do a bunch of swapout. So for the rest of the test 2.4 has an additional 8MB of cache available.

The problem of write activity causing swapout was fixed in 2.5. It does not swap out at all in this test. But this time, we want it to.

End result: 2.4 has ~20 megabytes of cache for the test and 2.5 has ~12
megabytes. The working pagecache set is around 16 MB, so we're right on
the edge - it makes 2.5 run 10x slower. You can get most of this back by boosting /proc/sys/vm/swappiness. I think the default of 60 is too unswappy really. I run my machines at 80.

Tuning swappiness doesn't get all the performance back. 2.5's memory footprint is generally larger - we still need to work that down.

If this was a real database server I'd expect that memory would end up getting swapped out anyway. But it doesn't happen in this test, which is actually quite light in its I/O demands.

With mem=128m, 2.5 is 10% faster than 2.4. Some of this is due to the enhancements to copy_*_user() for poorly-aligned copies on Intel CPUs.

Swap problem can be generalized. Let's consider these real-world example pairs:

* cache/RAM,
* local node RAM/remote node RAM (in a NUMA box)
* RAM/disk
* local disk/networked storage
* RAM/fast solid storage "disk" (USB Flash or IDE built from DRAM) (etc)

We have faster storage and slower storage.
We want to swap unused data from faster one for needed data on slower one. The larger the speed gap between the two, the more we feel the pain when our swap algorithms go wrong.

Note that speed differences (ratios) are very different:
from 1/5 to 1/1000000.

I wonder whether swappiness should be related to the speed ratio between storage types? How exactly?

Having to play with tunables is not an ideal way to go, I hate to think that Andrew's (and others) work can go down the drain at the very next technology jump.
--
vda

It doesn't matter. Assuming the latency of the swap device is the same as the filesystem device it cancels out. We're simply trying to minimise the total amount of I/O.

It's constant-access-time mass storage technology which will toss 20 years development down the gurgler. Top to bottom, everything is designed to support the locality=bandwidth characteristics of spinning disks.