• INN performance curve - why so much time dealing with the history file?

    From Jesse Rehmer@21:1/5 to All on Wed Jul 26 02:28:24 2023
    Now that I've got faster hardware and have had a chance to feed over 184 million articles to a new server, I notice a steep decline in performance from the beginning of the process to the end. When looking at the news.daily output it appears the majority of the time is spent dealing with the history file. I would expect article/overview writing or perl filtering to take more time, but perhaps there is more to dealing with the history file than I understand.<div><div>Is this kind of curve in performance degradation expected as the history file grows?</div><div></div><div>Timer output (note I didn't
    run news.daily until many days after injection stopped, accounting for the
    huge idle time):</div><div></div><div>INND timer:</div><div>Code region
    Time Pct Invoked Min(ms) Avg(ms) Max(ms)</div><div>article cancel 00:05:22.727 0.0% 205040 0.021 1.574
    7.677</div><div>article cleanup 00:05:44.900 0.0% 183854425 0.002
    0.002 0.002</div><div>article logging 00:11:56.897 0.1% 184142520
    0.003 0.004 0.005</div><div>article parse 00:30:34.354 0.2% 265195021 0.005 0.007 0.011</div><div>article write 00:43:24.939
    0.3% 183809673 0.010 0.014 0.024</div><div>data move
    00:01:08.029 0.0% 95351907 0.000 0.001
    0.002</div><div>hisgrep/artcncl 00:04:05.556 0.0% 205040 0.007
    1.198 4.204</div><div>history grep 00:00:00.000 0.0% 0
    0.000 0.000 0.000</div><div>history lookup 49:09:14.755 21.9% 183854425 0.001 0.962 2.154</div><div>history sync 00:00:01.261
    0.0% 2681 0.000 0.470 121.000</div><div>history write 41:34:50.164 18.5% 183854156 0.012 0.814 1.747</div><div>idle
    120:16:16.894 53.6% 22762294 0.003 19.022 600095.000</div><div>nntp read 00:12:29.088 0.1% 83339892 0.004
    0.009 0.012</div><div>overview write 02:45:18.889 1.2% 183809673
    0.026 0.054 0.101</div><div>perl filter 07:57:01.509 3.5% 183854156 0.124 0.156 0.251</div><div>python filter 00:06:03.073
    0.0% 183854156 0.000 0.002 0.014</div><div>site send
    00:00:00.000 0.0% 0 0.000 0.000 0.000</div><div></div><div>TOTAL: 224:33:0 223:43:33.035 99.6% -
    - - -</div><div></div><div>Performance shown by the hourly breakdown matches what I see with other metrics such as bandwidth, disk I/O, etc. There is a steady decline in all of those numbers as time went on. Note I have article size logging turned off, was trying trim down as much logging as possible.</div><div></div><div>Incoming articles:</div><div>Date
    Articles %Arts Art/sec Size %Size KB/sec</div><div>Jul 16 10:03:43 - 10:59:59 6608118 3.6% 1956.80 0.0 KB 0.0%
    0.00</div><div>Jul 16 11:00:00 - 11:59:59 13467714 7.3% 3741.03 0.0 KB
    0.0% 0.00</div><div>Jul 16 12:00:00 - 12:59:59 8000940 4.3% 2222.48
    0.0 KB 0.0% 0.00</div><div>Jul 16 13:00:00 - 13:59:59 5748819 3.1% 1596.89 0.0 KB 0.0% 0.00</div><div>Jul 16 14:00:00 - 14:59:59 5122241
    2.8% 1422.84 0.0 KB 0.0% 0.00</div><div>Jul 16 15:00:00 - 15:59:59 4287868 2.3% 1191.07 0.0 KB 0.0% 0.00</div><div>Jul 16 16:00:00 - 16:59:59 4034400 2.2% 1120.67 0.0 KB 0.0% 0.00</div><div>Jul 16 17:00:00 - 17:59:59 3548680 1.9% 985.74 0.0 KB 0.0%
    0.00</div><div>Jul 16 18:00:00 - 18:59:59 3238737 1.8% 899.65 0.0 KB
    0.0% 0.00</div><div>Jul 16 19:00:00 - 19:59:59 3179352 1.7% 883.15
    0.0 KB 0.0% 0.00</div><div>Jul 16 20:00:00 - 20:59:59 2861511 1.6% 794.86 0.0 KB 0.0% 0.00</div><div>Jul 16 21:00:00 - 21:59:59 2557273
    1.4% 710.35 0.0 KB 0.0% 0.00</div><div>Jul 16 22:00:00 - 22:59:59 2476205 1.3% 687.83 0.0 KB 0.0% 0.00</div><div>Jul 16 23:00:00 - 23:59:59 2470653 1.3% 686.29 0.0 KB 0.0% 0.00</div><div>Jul 17 00:00:00 - 00:59:59 2377684 1.3% 660.47 0.0 KB 0.0%
    0.00</div><div>Jul 17 01:00:00 - 01:59:59 2214251 1.2% 615.07 0.0 KB
    0.0% 0.00</div><div>Jul 17 02:00:00 - 02:59:59 2160533 1.2% 600.15
    0.0 KB 0.0% 0.00</div><div>Jul 17 03:00:00 - 03:59:59 2138072 1.2% 593.91 0.0 KB 0.0% 0.00</div><div>Jul 17 04:00:00 - 04:59:59 2064017
    1.1% 573.34 0.0 KB 0.0% 0.00</div><div>Jul 17 05:00:00 - 05:59:59 1975211 1.1% 548.67 0.0 KB 0.0% 0.00</div><div>Jul 17 06:00:00 - 06:59:59 1902269 1.0% 528.41 0.0 KB 0.0% 0.00</div><div>Jul 17 07:00:00 - 07:59:59 1859862 1.0% 516.63 0.0 KB 0.0%
    0.00</div><div>Jul 17 08:00:00 - 08:59:59 1826617 1.0% 507.39 0.0 KB
    0.0% 0.00</div><div>Jul 17 09:00:00 - 09:59:59 1803042 1.0% 500.85
    0.0 KB 0.0% 0.00</div><div>Jul 17 10:00:00 - 10:59:59 1779735 1.0% 494.37 0.0 KB 0.0% 0.00</div><div>Jul 17 11:00:00 - 11:59:59 1724235
    0.9% 478.95 0.0 KB 0.0% 0.00</div><div>Jul 17 12:00:00 - 12:59:59 1694753 0.9% 470.76 0.0 KB 0.0% 0.00</div><div>Jul 17 13:00:00 - 13:59:59 1687997 0.9% 468.89 0.0 KB 0.0% 0.00</div><div>Jul 17 14:00:00 - 14:59:59 1689864 0.9% 469.41 0.0 KB 0.0%
    0.00</div><div>Jul 17 15:00:00 - 15:59:59 1667083 0.9% 463.08 0.0 KB
    0.0% 0.00</div><div>Jul 17 16:00:00 - 16:59:59 1614929 0.9% 448.59
    0.0 KB 0.0% 0.00</div><div>Jul 17 17:00:00 - 17:59:59 1551492 0.8% 430.97 0.0 KB 0.0% 0.00</div><div>Jul 17 18:00:00 - 18:59:59 1510100
    0.8% 419.47 0.0 KB 0.0% 0.00</div><div>Jul 17 19:00:00 - 19:59:59 1516064 0.8% 421.13 0.0 KB 0.0% 0.00</div><div>Jul 17 20:00:00 - 20:59:59 1504238 0.8% 417.84 0.0 KB 0.0% 0.00</div><div>Jul 17 21:00:00 - 21:59:59 1511102 0.8% 419.75 0.0 KB 0.0%
    0.00</div><div>Jul 17 22:00:00 - 22:59:59 1498772 0.8% 416.33 0.0 KB
    0.0% 0.00</div><div>Jul 17 23:00:00 - 23:59:59 1459980 0.8% 405.55
    0.0 KB 0.0% 0.00</div><div>Jul 18 00:00:00 - 00:59:59 1414708 0.8% 392.97 0.0 KB 0.0% 0.00</div><div>Jul 18 01:00:00 - 01:59:59 1404954
    0.8% 390.26 0.0 KB 0.0% 0.00</div><div>Jul 18 02:00:00 - 02:59:59 1376430 0.7% 382.34 0.0 KB 0.0% 0.00</div><div>Jul 18 03:00:00 - 03:59:59 1378259 0.7% 382.85 0.0 KB 0.0% 0.00</div><div>Jul 18 04:00:00 - 04:59:59 1390281 0.8% 386.19 0.0 KB 0.0%
    0.00</div><div>Jul 18 05:00:00 - 05:59:59 1386335 0.8% 385.09 0.0 KB
    0.0% 0.00</div><div>Jul 18 06:00:00 - 06:59:59 1355294 0.7% 376.47
    0.0 KB 0.0% 0.00</div><div>Jul 18 07:00:00 - 07:59:59 1327220 0.7% 368.67 0.0 KB 0.0% 0.00</div><div>Jul 18 08:00:00 - 08:59:59 1296572
    0.7% 360.16 0.0 KB 0.0% 0.00</div><div>Jul 18 09:00:00 - 09:59:59 1276394 0.7% 354.55 0.0 KB 0.0% 0.00</div><div>Jul 18 10:00:00 - 10:59:59 1280991 0.7% 355.83 0.0 KB 0.0% 0.00</div><div>Jul 18 11:00:00 - 11:59:59 1276734 0.7% 354.65 0.0 KB 0.0%
    0.00</div><div>Jul 18 12:00:00 - 12:59:59 1330133 0.7% 369.48 0.0 KB
    0.0% 0.00</div><div>Jul 18 13:00:00 - 13:59:59 1321197 0.7% 367.00
    0.0 KB 0.0% 0.00</div><div>Jul 18 14:00:00 - 14:59:59 1270985 0.7% 353.05 0.0 KB 0.0% 0.00</div><div>Jul 18 15:00:00 - 15:59:59 1251052
    0.7% 347.51 0.0 KB 0.0% 0.00</div><div>Jul 18 16:00:00 - 16:59:59 1238624 0.7% 344.06 0.0 KB 0.0% 0.00</div><div>Jul 18 17:00:00 - 17:59:59 1227250 0.7% 340.90 0.0 KB 0.0% 0.00</div><div>Jul 18 18:00:00 - 18:59:59 1203798 0.7% 334.39 0.0 KB 0.0%
    0.00</div><div>Jul 18 19:00:00 - 19:59:59 1225960 0.7% 340.54 0.0 KB
    0.0% 0.00</div><div>Jul 18 20:00:00 - 20:59:59 1221275 0.7% 339.24
    0.0 KB 0.0% 0.00</div><div>Jul 18 21:00:00 - 21:59:59 1199617 0.7% 333.23 0.0 KB 0.0% 0.00</div><div>Jul 18 22:00:00 - 22:59:59 1178009
    0.6% 327.22 0.0 KB 0.0% 0.00</div><div>Jul 18 23:00:00 - 23:59:59 1154628 0.6% 320.73 0.0 KB 0.0% 0.00</div><div>Jul 19 00:00:00 - 00:59:59 1145227 0.6% 318.12 0.0 KB 0.0% 0.00</div><div>Jul 19 01:00:00 - 01:59:59 1111125 0.6% 308.65 0.0 KB 0.0%
    0.00</div><div>Jul 19 02:00:00 - 02:59:59 1095739 0.6% 304.37 0.0 KB
    0.0% 0.00</div><div>Jul 19 03:00:00 - 03:59:59 1093542 0.6% 303.76
    0.0 KB 0.0% 0.00</div><div>Jul 19 04:00:00 - 04:59:59 1089209 0.6% 302.56 0.0 KB 0.0% 0.00</div><div>Jul 19 05:00:00 - 05:59:59 1090842
    0.6% 303.01 0.0 KB 0.0% 0.00</div><div>Jul 19 06:00:00 - 06:59:59 1074421 0.6% 298.45 0.0 KB 0.0% 0.00</div><div>Jul 19 07:00:00 - 07:59:59 1054212 0.6% 292.84 0.0 KB 0.0% 0.00</div><div>Jul 19 08:00:00 - 08:59:59 1044447 0.6% 290.12 0.0 KB 0.0%
    0.00</div><div>Jul 19 09:00:00 - 09:59:59 931031 0.5% 258.62 0.0 KB
    0.0% 0.00</div><div>Jul 19 10:00:00 - 10:59:59 1079244 0.6% 299.79
    0.0 KB 0.0% 0.00</div><div>Jul 19 11:00:00 - 11:59:59 1069259 0.6% 297.02 0.0 KB 0.0% 0.00</div><div>Jul 19 12:00:00 - 12:59:59 1067895
    0.6% 296.64 0.0 KB 0.0% 0.00</div><div>Jul 19 13:00:00 - 13:59:59 1056197 0.6% 293.39 0.0 KB 0.0% 0.00</div><div>Jul 19 14:00:00 - 14:59:59 1064508 0.6% 295.70 0.0 KB 0.0% 0.00</div><div>Jul 19 15:00:00 - 15:59:59 1053532 0.6% 292.65 0.0 KB 0.0%
    0.00</div><div>Jul 19 16:00:00 - 16:59:59 1035573 0.6% 287.66 0.0 KB
    0.0% 0.00</div><div>Jul 19 17:00:00 - 17:59:59 1017242 0.6% 282.57
    0.0 KB 0.0% 0.00</div><div>Jul 19 18:00:00 - 18:59:59 1019435 0.6% 283.18 0.0 KB 0.0% 0.00</div><div>Jul 19 19:00:00 - 19:59:59 1013209
    0.5% 281.45 0.0 KB 0.0% 0.00</div><div>Jul 19 20:00:00 - 20:59:59 1003259 0.5% 278.68 0.0 KB 0.0% 0.00</div><div>Jul 19 21:00:00 - 21:59:59 998980 0.5% 277.49 0.0 KB 0.0% 0.00</div><div>Jul 19 22:00:00 - 22:59:59 999129 0.5% 277.54 0.0 KB 0.0%
    0.00</div><div>Jul 19 23:00:00 - 23:59:59 1005058 0.5% 279.18 0.0 KB
    0.0% 0.00</div><div>Jul 20 00:00:00 - 00:59:59 1004154 0.5% 278.93
    0.0 KB 0.0% 0.00</div><div>Jul 20 01:00:00 - 01:59:59 983326 0.5% 273.15 0.0 KB 0.0% 0.00</div><div>Jul 20 02:00:00 - 02:59:59 984133
    0.5% 273.37 0.0 KB 0.0% 0.00</div><div>Jul 20 03:00:00 - 03:59:59 956548 0.5% 265.71 0.0 KB 0.0% 0.00</div><div>Jul 20 04:00:00 - 04:59:59 955865 0.5% 265.52 0.0 KB 0.0% 0.00</div><div>Jul 20 05:00:00 - 05:59:59 949230 0.5% 263.68 0.0 KB 0.0%
    0.00</div><div>Jul 20 06:00:00 - 06:59:59 938727 0.5% 260.76 0.0 KB
    0.0% 0.00</div><div>Jul 20 07:00:00 - 07:59:59 947608 0.5% 263.22
    0.0 KB 0.0% 0.00</div><div>Jul 20 08:00:00 - 08:59:59 955909 0.5% 265.53 0.0 KB 0.0% 0.00</div><div>Jul 20 09:00:00 - 09:59:59 951293
    0.5% 264.25 0.0 KB 0.0% 0.00</div><div>Jul 20 10:00:00 - 10:59:59 939124 0.5% 260.87 0.0 KB 0.0% 0.00</div><div>Jul 20 11:00:00 - 11:59:59 945338 0.5% 262.59 0.0 KB 0.0% 0.00</div><div>Jul 20 12:00:00 - 12:59:59 913587 0.5% 253.77 0.0 KB 0.0%
    0.00</div><div>Jul 20 13:00:00 - 13:59:59 926263 0.5% 257.30 0.0 KB
    0.0% 0.00</div><div>Jul 20 14:00:00 - 14:59:59 930761 0.5% 258.54
    0.0 KB 0.0% 0.00</div><div>Jul 20 15:00:00 - 15:59:59 908011 0.5% 252.23 0.0 KB 0.0% 0.00</div><div>Jul 20 16:00:00 - 16:59:59 863137
    0.5% 239.76 0.0 KB 0.0% 0.00</div><div>Jul 20 17:00:00 - 17:59:59 851113 0.5% 236.42 0.0 KB 0.0% 0.00</div><div>Jul 20 18:00:00 - 18:59:59 843252 0.5% 234.24 0.0 KB 0.0% 0.00</div><div>Jul 20 19:00:00 - 19:25:57 218494 0.1% 140.33 0.0 KB 0.0%
    0.00</div></div>

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)