Bug 197516 - TRIM on gmirror is slow and results in inresponsive system
Summary: TRIM on gmirror is slow and results in inresponsive system
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 10.1-STABLE
Hardware: Any Any
: --- Affects Some People
Assignee: Alexander Motin
URL: https://forums.freebsd.org/threads/bo...
Keywords:
Depends on:
Blocks:
 
Reported: 2015-02-10 13:44 UTC by Robert Schulze
Modified: 2015-03-31 12:49 UTC (History)
1 user (show)

See Also:


Attachments
Test results (48.86 KB, text/plain)
2015-02-10 13:44 UTC, Robert Schulze
no flags Details
Test script (308 bytes, text/plain)
2015-02-10 13:45 UTC, Robert Schulze
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Robert Schulze 2015-02-10 13:44:40 UTC
Created attachment 152841 [details]
Test results

After deleting a (fairly) large file on an ssd based gmirror, the system becomes inresponsive for a certain period of time. This seems to be caused by the calls to BIO_DELETE on the mirror, which can be monitored with gstat -d. Doing exactly the same on an unmirrored UFS leaves the system unimpacted, as the DELETE operation takes only a fraction of time there.

I've also tried tuning the behaviour of the mirror with the sysctl kern.geom.dev.delete_max_sectors. Setting it to 0 oder greater values than the default of 262144 does not significantly affect the performance.

A script which I used to test with is attached, also the results reformatted in a better readable way.

The system is non productive and can be used to figure out what is going wrong. Any help is appreciated.
Comment 1 Robert Schulze 2015-02-10 13:45:14 UTC
Created attachment 152842 [details]
Test script
Comment 2 Robert Schulze 2015-02-11 10:26:32 UTC
I've added a debug statement to sys/ufs/ffs/ffs_alloc.c to compare the calls between a non-mirrored ufs and a gmirrored one:

--- sys/ufs/ffs/ffs_alloc.c.orig        2015-02-09 16:24:06.000000000 +0100
+++ sys/ufs/ffs/ffs_alloc.c     2015-02-11 10:17:13.000000000 +0100
@@ -2313,6 +2313,9 @@
        bip->bio_length = size;
        bip->bio_caller2 = tp;
 
+       printf("%s: starting BIO_DELETE for %jd bytes @ offset %jd\n", 
+           __func__, size, bip->bio_offset);
+
        mp = UFSTOVFS(ump);
        vn_start_secondary_write(NULL, &mp, 0);
        g_io_request(bip, (struct g_consumer *)devvp->v_bufobj.bo_private);

Creating a 100m file and deleting it afterwards results in the same amount of calls to BIO_DELETE in both cases.

Changing kern.geom.dev.delete_max_sectors does not influence the calls.
Comment 3 Robert Schulze 2015-02-13 14:02:14 UTC
One more thing to add: the behaviour of the delete calls varies extremely. I subsequently created and deleted a 1G file and the whole delete procedure (monitored via iostat) took 32, 14, 10, 80 seconds to complete.

I've disabled everything except syslog and ssh.
Here is the script:

--- 8< ----------------------------------------------
#!/bin/sh

FSZ=1000
FILE=/usr/${FSZ}M

echo "creating ${FSZ}M file $FILE..."
dd if=/dev/random of=$FILE bs=1k count=${FSZ}k
sync
echo "done, hit enter to delete file..."
read noop

echo "deleting file..."
unlink $FILE
sync
echo "done"
echo "running iostat -w1 ada0 ada1"

iostat -w1 ada0 ada1
--- 8< ----------------------------------------------

And the results:
1) 00:32.231

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   1   115 52.20 591 30.13  52.13 592 30.15   0  0  8  0 91
   0   343 32.00 4040 126.24  32.00 4033 126.04   0  0 22  0 78
   0   223 32.00 1791 55.98  32.00 1796 56.12   0  0 24  0 76
   0   203 32.00 1567 48.98  32.00 1567 48.95   0  0 19  0 81
   0   184 32.00 4414 137.94  32.00 4426 138.30   0  0 21  0 79
   0   333 32.00 2098 65.57  32.00 2092 65.36   0  0 24  0 75
   0   168 32.00 1556 48.61  32.00 1567 48.96   0  0 24  0 76
   0   177 32.00 1311 40.98  32.00 1310 40.95   0  0 24  0 76
   0   191 32.00 1153 36.04  32.00 1150 35.95   0  0 23  0 77
   0   182 32.00 1052 32.88  32.00 1040 32.51   0  0 21  0 78
   0   178 32.00 944 29.51  32.00 971 30.33   0  0 24  0 76
   0   181 32.00 889 27.78  32.00 882 27.57   0  0 23  0 77
   0   179 32.00 811 25.34  32.00 829 25.90   0  0 24  0 76
   0   189 32.00 778 24.33  32.00 755 23.58   0  0 24  0 76
   0   191 32.00 640 19.99  32.00 624 19.49   0  0 23  0 77
   0   164 32.00 469 14.67  32.00 470 14.70   0  0 21  0 79
   0   177 32.00 500 15.61  32.00 596 18.64   0  0 22  0 77
   0   175 32.00 605 18.90  32.00 572 17.87   0  0 24  0 76
   0   183 32.00 565 17.65  32.00 523 16.35   0  0 23  0 77
   0   186 32.00 701 21.92  32.00 729 22.77   0  0 23  0 77
   0   189 32.00 445 13.91  32.00 491 15.35   0  0 24  0 76
   0   177 32.00 467 14.58  32.00 403 12.61   0  0 24  0 76
   0   313 32.00 385 12.02  32.00 437 13.65   0  0 24  0 76
   0   181 32.00 419 13.11  32.00 351 10.96   0  0 24  0 76
   0   175 32.00 366 11.44  32.00 361 11.29   0  0 23  0 77
   0   180 32.00 300  9.39  32.00 387 12.10   0  0 25  0 75
   0   187 32.00 363 11.34  32.00 285  8.91   0  0 22  0 78
   0   178 32.00 310  9.67  32.00 307  9.58   0  0 24  0 76
   0   191 32.00 260  8.14  32.00 320  9.99   0  0 24  0 76
   0   177 32.00 319  9.96  32.00 254  7.93   0  0 18  0 82
   0   194 31.95 1134 35.38  31.95 1125 35.11   0  0 17  0 83
   0   210  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0   197  0.00   0  0.00   4.00   2  0.01   0  0  0  0 100
   0    93  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    94  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

2) 00:14.720

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   1   113 52.12 564 28.69  52.06 565 28.71   0  0  8  0 92
   0   340 32.00 4035 126.11  32.00 4035 126.11   0  0 23  0 77
   0   227 32.00 1867 58.36  32.00 1868 58.38   0  0 23  0 77
   0   200 32.00 1602 50.05  32.00 1600 49.99   0  0 19  0 81
   0   238 31.99 4647 145.16  31.99 4629 144.60   0  0 22  0 78
   0   215 32.00 2156 67.38  32.00 2187 68.35   0  0 25  0 75
   0   193 32.00 1618 50.56  32.00 1687 52.71   0  0 24  0 76
   0   195 32.00 1305 40.79  32.00 1401 43.77   0  0 25  0 75
   0   193 32.00 1194 37.33  32.00 1178 36.80   0  0 25  0 75
   0   156 32.00 1180 36.86  32.00 1035 32.34   0  0 22  0 77
   0   193 32.00 5468 170.89  32.00 5085 158.89   0  0 21  0 78
   0   203 32.00 3108 97.14  32.00 3496 109.24   0  0 23  0 76
   0   206 32.00 1798 56.19  32.00 1797 56.16   0  0 21  0 78
   0   175 32.00 768 23.99  32.00 767 23.96   0  0  7  0 92
   0   165  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    71  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    58  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

3) 00:10.303

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   1   111 52.06 560 28.46  52.00 561 28.47   0  0  8  0 92
   0   328 32.00 10263 320.71  32.00 10138 316.80   0  0 27  0 73
   0   232 32.00 3957 123.65  32.00 3881 121.27   0  0 26  0 74
   0   161 32.00 3015 94.21  32.00 2946 92.06   0  0 25  0 75
   0   157 32.00 2593 81.02  32.00 2531 79.09   0  0 26  0 74
   0   156 32.00 3482 108.82  32.00 3558 111.19   0  0 22  0 78
   0   159 32.00 2002 62.57  32.00 1923 60.09   0  0 26  0 74
   0   148 32.00 1780 55.62  32.00 1935 60.47   0  0 22  0 78
   0   181 32.00 1985 62.03  32.00 2152 67.26   0  0 19  0 81
   0   181 32.00 1898 59.33  32.00 1899 59.36   0  0  9  0 91
   0   183  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0   168  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    58  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

4) 01:20.279

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   1   110 52.00 562 28.52  51.94 563 28.54   0  0  8  0 92
   0   350 32.00 4955 154.83  32.00 5004 156.39   0  0 27  0 73
   0   218 32.00 1917 59.92  32.00 1934 60.45   0  0 26  0 74
   0   160 32.00 1483 46.35  32.00 1477 46.14   0  0 25  0 75
   0   156 32.00 1226 38.32  32.00 1269 39.67   0  0 24  0 76
   0   137 32.00 1104 34.51  32.00 1097 34.28   0  0 25  0 75
   0   139 32.00 998 31.19  32.00 994 31.07   0  0 26  0 74
   0   138 32.00 908 28.37  32.00 920 28.75   0  0 26  0 74
   0   153 32.00 832 25.99  32.00 858 26.81   0  0 25  0 75
   0   153 32.00 773 24.17  32.00 786 24.55   0  0 24  0 76
   0   142 32.00 721 22.54  32.00 737 23.05   0  0 25  0 75
   0   161 32.00 679 21.22  32.00 670 20.95   0  0 25  0 75
   0   156 32.00 646 20.20  32.00 608 18.99   0  0 26  0 74
   0   183 32.00 584 18.26  32.00 565 17.65   0  0 25  0 75
   0   190 32.00 551 17.23  32.00 528 16.51   0  0 26  0 74
   0   167 32.00 500 15.63  32.00 496 15.50   0  0 25  0 75
   0   173 32.00 460 14.37  32.00 468 14.64   0  0 24  0 76
   0   169 32.00 423 13.22  32.00 444 13.87   0  0 24  0 76
   0   168 32.00 393 12.29  32.00 413 12.91   0  0 25  0 75
   0   172 32.00 379 11.85  32.00 375 11.73   0  0 25  0 75
   0   168 32.00 341 10.67  32.00 364 11.37   0  0 26  0 74
   0   149 32.00 348 10.88  32.00 318  9.94   0  0 25  0 75
   0   280 32.00 303  9.47  32.00 325 10.17   0  0 25  0 75
   0   169 32.00 298  9.32  32.00 297  9.29   0  0 24  0 76
   0   171 32.00 290  9.05  32.00 271  8.47   0  0 25  0 75
   0   177 32.00 269  8.41  32.00 263  8.23   0  0 25  0 75
   0   176 32.00 246  7.67  32.00 230  7.20   0  0 25  0 75
   0   179 32.00 188  5.88  32.00 191  5.97   0  0 25  0 75
   0   175 32.00 185  5.79  32.00 194  6.06   0  0 25  0 75
   0   201 31.98 1368 42.72  31.98 1429 44.63   0  0 23  0 77
   0   190 32.00 198  6.17  32.00 257  8.03   0  0 26  0 74
   0   172 32.00 159  4.97  32.00 233  7.28   0  0 26  0 74
   0   170 32.00 151  4.73  32.00 229  7.17   0  0 25  0 75
   0   181 32.00 143  4.47  31.88 227  7.06   0  0 26  0 74
   0   196 32.00 132  4.14  32.00 228  7.11   0  0 25  0 75
   0   133 32.00 125  3.92  32.00 225  7.05   0  0 25  0 75
   0   168 32.00 123  3.85  32.00 220  6.88   0  0 25  0 75
   0   184 32.00 113  3.53  32.00 221  6.91   0  0 25  0 75
   0   188 32.00 116  3.62  32.00 214  6.67   0  0 23  0 77
   0   214 31.85 180  5.59  32.00 145  4.53   0  0 24  0 76
   0   190 32.00 183  5.70  32.00 135  4.20   0  0 24  0 76
   0   161 32.00 182  5.67  32.00 127  3.97   0  0 23  0 77
   0   175 32.00 485 15.17  32.00 185  5.78   0  0 24  0 76
   0   286 32.00 279  8.73  32.00 261  8.17   0  0 23  0 77
   0   173 32.00 171  5.35  32.00 179  5.59   0  0 25  0 75
   0   168 32.00 167  5.23  32.00 110  3.44   0  0 24  0 76
   0   173 32.00 150  4.68  32.00 123  3.84   0  0 24  0 76
   0   169 32.00 152  4.75  32.00 118  3.68   0  0 23  0 77
   0   177 32.00 151  4.73  32.00 112  3.51   0  0 24  0 76
   0   173 32.00 154  4.81  32.00 109  3.40   0  0 24  0 76
   0   171 32.00 151  4.73  32.00 105  3.29   0  0 24  0 76
   0   133 32.00 151  4.73  32.00 103  3.20   0  0 24  0 76
   0   151 32.00 149  4.64  32.00 101  3.15   0  0 23  0 77
   0   185 32.00 132  4.12  32.00 116  3.63   0  0 24  0 76
   0   181 32.00 140  4.37  32.00 107  3.35   0  0 24  0 76
   0   180 32.00 138  4.30  32.00 104  3.24   0  0 23  0 77
   0   183 32.00 137  4.30  32.00 104  3.24   0  0 24  0 76
   0   177 32.00 120  3.75  32.00 118  3.69   0  0 24  0 76
   0   144 32.00 121  3.79  32.00 115  3.59   0  0 23  0 77
   0   174 32.00 123  3.84  32.00 111  3.47   0  0 24  0 76
   0    58 32.00 113  3.52  32.00 120  3.76   0  0 25  0 75
   0   188 32.00 114  3.57  32.00 113  3.54   0  0 24  0 75
   0   292 32.00 123  3.85  32.00 103  3.20   0  0 23  0 77
   0   171 32.00 113  3.53  32.00 111  3.47   0  0 25  0 75
   0   291 32.00 113  3.53  32.00 109  3.41   0  0 25  0 75
   0   174 32.00  87  2.73  32.00 135  4.20   0  0 26  0 74
   0   164 32.00  87  2.73  32.00 133  4.15   0  0 24  0 76
   0   169 32.00 100  3.12  32.00 118  3.67   0  0 24  0 76
   0   172 32.00 120  3.76  32.00  94  2.94   0  0 24  0 76
   0   167 32.00 122  3.80  32.00  91  2.85   0  0 20  0 80
   0   163 32.00 126  3.94  32.00  87  2.71   0  0 17  0 83
   0   207 32.00 124  3.89  32.00 101  3.14   0  0 18  0 82
   0   224 32.00 102  3.19  32.00 102  3.19   0  0 19  0 81
   0   156 32.00 102  3.20  32.00 101  3.17   0  0 18  0 82
   0    60 32.00 101  3.15  32.00 101  3.15   0  0 17  0 83
   0   177 32.00 160  5.00  32.00 145  4.52   0  0 21  0 79
   0   213 31.90 548 17.08  31.91 563 17.55   0  0  6  0 94
   0   209  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0   193  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

Please note that this issue is also mentioned in the forums.
Comment 4 Robert Schulze 2015-02-13 14:23:39 UTC
Running the script from comment #3 on a gmirror with only one component, the results are the following:

1) 9s
       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   1    96 12.50   7  0.08  111.02 171 18.59   0  0  4  0 96
   0   184  0.00   0  0.00  32.00 6613 206.65   0  0 18  0 82
   0    59  0.00   0  0.00  32.00 3222 100.70   0  0 18  0 82
   0    63  0.00   0  0.00  32.00 2817 88.02   0  0 18  0 82
   0    62  0.00   0  0.00  32.00 2447 76.46   0  0 18  0 82
   0    58  0.00   0  0.00  32.00 2634 82.31   0  0 16  0 84
   0    58  0.00   0  0.00  32.00 3540 110.62   0  0 13  0 87
   0    59  0.00   0  0.00  32.00 3682 115.06   0  0 13  0 87
   0    59  0.00   0  0.00  32.00 5461 170.65   0  0  6  0 94
   0    59  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    58  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

2) 5s

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   0    61 12.53   3  0.04  62.84 465 28.55   0  0  5  0 95
   0   172  0.00   0  0.00  32.00 13636 426.09   0  0 21  0 79
   0    60  0.00   0  0.00  32.00 8488 265.26   0  0 20  0 80
   0    59  0.00   0  0.00  32.00 6232 194.73   0  0 13  0 87
   0    59  0.00   0  0.00  32.00 1755 54.86   0  0  4  0 96
   0    58  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100


3) 9s

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   0    46 12.52   2  0.03  57.60 569 32.03   0  0  5  0 95
   0   172  0.00   0  0.00  32.00 10313 322.27   0  0 22  0 78
   0    60  0.00   0  0.00  32.00 3561 111.27   0  0 17  0 83
   0    63  0.00   0  0.00  32.00 2442 76.32   0  0 18  0 82
   0    62  0.00   0  0.00  32.00 2167 67.71   0  0 20  0 80
   0    62  0.00   0  0.00  32.00 2090 65.32   0  0 20  0 80
   0    61  0.00   0  0.00  32.00 2042 63.80   0  0 17  0 83
   0    61  0.00   0  0.00  32.00 2368 74.00   0  0 14  0 86
   0    61  0.00   0  0.00  32.00 5914 184.81   0  0 10  0 90
   0    62  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    61  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

4) 14s

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   0    38 12.51   2  0.02  55.61 586 31.84   0  0  5  0 95
   0   172  0.00   0  0.00  32.00 9241 288.79   0  0 19  0 81
   0    63  0.00   0  0.00  32.00 3067 95.85   0  0 19  0 81
   0    62  0.00   0  0.00  32.00 2305 72.03   0  0 19  0 81
   0    62  0.00   0  0.00  32.00 1994 62.32   0  0 19  0 81
   0    61  0.00   0  0.00  32.00 1784 55.75   0  0 18  0 82
   0    60  0.00   0  0.00  32.00 1610 50.32   0  0 18  0 82
   0    61  0.00   0  0.00  32.00 1446 45.20   0  0 18  0 82
   0    62  0.00   0  0.00  32.00 1394 43.58   0  0 19  0 81
   0    60  0.00   0  0.00  32.00 1800 56.26   0  0 12  0 88
   0    61  0.00   0  0.00  32.00 1840 57.51   0  0 14  0 86
   0    61  0.00   0  0.00  32.00 1900 59.37   0  0 12  0 88
   0    61  0.00   0  0.00  32.00 1961 61.28   0  0 13  0 87
   0    61  0.00   0  0.00  31.93 816 25.46   0  0  5  0 95
   0    57  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100

5) 7s

       tty            ada0             ada1             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   0    33 12.50   1  0.02  54.56 581 30.94   0  0  5  0 95
   0   183  0.00   0  0.00  32.00 13082 408.80   0  0 23  0 76
   0    60  0.00   0  0.00  32.00 4958 154.95   0  0 21  0 79
   0    59  0.00   0  0.00  32.00 3581 111.92   0  0 19  0 81
   0    59  0.00   0  0.00  32.00 3308 103.36   0  0 13  0 87
   0    59  0.00   0  0.00  32.00 3331 104.10   0  0 13  0 87
   0    59  0.00   0  0.00  31.98 2621 81.85   0  0 10  0 90
   0    58  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
   0    58  0.00   0  0.00   0.00   0  0.00   0  0  0  0 100
Comment 5 Alexander Motin freebsd_committer 2015-03-31 10:02:14 UTC
r280757 commit in head is supposed to fix this problem. I'll merge in to stable in couple weeks. Please test that change before if you can.
Comment 6 Robert Schulze 2015-03-31 12:49:41 UTC
(In reply to Alexander Motin from comment #5)
The revision r280757 of g_mirror.c indeed fixes the behaviour. I'd like to thank you very much for your efforts.