Into.the.Void.

I am writing this post to provide some statistics on athcool + sata_sil usage. The results are horrible.

Athcool is a small utility, enabling/disabling Powersaving mode for AMD Athlon/Duron processors.
The homepage of the utility has a big fat warning as well:

WARNING: Depending on your motherboard and/or hardware components, enabling powersaving mode may cause:

* noisy or distorted sound playback
* a slowdown in harddisk performance
* system locks or instability

The Gentoo ebuild also has these warnings:

ewarn “WARNING: Depending on your motherboard and/or hardware components,”
ewarn “enabling powersaving mode may cause:”
ewarn ” * noisy or distorted sound playback”
ewarn ” * a slowdown in harddisk performance”
ewarn ” * system locks or unpredictable behavior”
ewarn ” * file system corruption”
ewarn “If you met those problems, you should not use athcool. Please use”
ewarn “athcool AT YOUR OWN RISK!”

Ignoring all these warning I was using athcool for years on my old desktop box filled with 2 IDE disks. Never had any real problem at all, except for a some performance loss. The problem appeared when I first used a sata disk on motherboard’s, Gigabyte GA-7VAXP-A Ulta, sata controller which uses the sata_sil module.

Here are some tests using dd and vmstat. The two commands were run on different terminals at the same time:
1) athcool off
a) dd to IDE
(TERMINAL 1) user@box:~% vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
0 0 0 392296 19272 663892 0 0 0 56 260 332 0 0 100 0
1 0 0 813648 19344 245960 0 0 4 64604 486 849 4 58 14 24
0 1 0 769380 19388 289680 0 0 0 44032 399 890 3 30 0 67
0 2 0 769876 19388 290704 0 0 0 4 368 594 1 3 0 96
0 3 0 708372 19460 351120 0 0 0 40632 347 589 2 46 0 52
0 1 0 674272 19492 383928 0 0 0 53936 471 821 1 27 0 72
0 1 0 655796 19508 401744 0 0 0 17640 376 651 1 13 0 86
0 1 0 588712 19572 466880 0 0 0 65544 469 1024 9 40 0 51
1 1 0 579412 19584 478072 0 0 0 6148 368 852 5 8 0 87
0 2 0 504516 19664 550856 0 0 0 79104 414 817 3 52 0 45
1 0 0 453800 19712 600040 0 0 0 45420 350 616 4 30 0 66
0 1 0 414740 19748 637952 0 0 0 40872 401 700 3 26 0 71
0 1 0 367248 19792 684064 0 0 0 46112 357 619 5 32 0 63
1 1 0 360552 19804 693280 0 0 0 7240 421 795 2 8 0 90
2 1 0 268668 19896 782368 0 0 0 84768 385 722 5 65 0 30
2 1 0 230724 19932 819248 0 0 0 43672 378 598 2 27 0 71
1 1 0 184224 19976 864328 0 0 0 45080 349 587 5 27 0 68
0 1 0 142932 20016 904288 0 0 0 39960 369 653 1 33 0 66
1 1 0 136608 20032 913928 0 0 0 6400 337 523 2 11 0 87
0 1 0 46708 20120 1000568 0 0 0 90360 387 626 4 61 0 35
0 1 0 26508 14348 1025136 0 0 0 44048 346 633 1 29 0 70
0 1 0 23404 13368 1028324 0 0 0 42016 363 638 2 26 0 72
0 1 4 23776 11816 1028108 0 0 0 43048 336 631 0 30 0 70
1 1 4 24024 11000 1031428 0 0 0 26796 391 663 4 25 0 71
0 0 4 23652 11028 1032324 0 0 0 16836 336 648 2 14 18 66
0 0 4 23776 11028 1032324 0 0 0 0 278 397 1 0 99 0
(TERMINAL 2) user@box:~%dd if=/dev/zero of=/path/to/parition/on/IDE/disk/file bs=1024 count=1000000
1000000+0 records in
1000000+0 records out
1024000000 bytes (1.0 GB) copied, 22.8884 s, 44.7 MB/s

Pretty decent performace.

b) dd to SATA
(TERMINAL 1) user@box:~% vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
0 0 4 738008 21872 317948 0 0 0 0 308 427 2 0 98 0
0 0 4 738008 21880 317948 0 0 0 48 268 342 0 1 99 0
3 0 4 722508 21916 334312 0 0 4 8456 320 491 3 11 84 2
1 0 4 647612 22008 407372 0 0 0 80844 374 762 9 52 0 39
0 1 4 624796 22032 429996 0 0 0 22528 389 465 0 17 0 83
1 0 4 557836 22096 495032 0 0 0 64520 361 395 3 50 0 47
1 0 4 512576 22136 539012 0 0 0 44032 386 548 5 33 0 62
0 2 4 473640 22176 579080 0 0 0 38916 353 488 2 31 0 67
2 0 4 448220 22220 605548 0 0 0 23156 399 434 3 20 0 77
0 1 4 381880 22280 669192 0 0 0 60492 353 374 2 48 0 50
1 0 4 331784 22328 717848 0 0 0 49272 388 431 3 36 0 61
1 2 4 286648 22372 761716 0 0 0 43120 345 366 4 33 0 63
0 3 4 249696 22408 799240 0 0 0 46832 391 437 2 30 0 68
1 3 4 212124 22448 837352 0 0 0 28460 351 446 3 29 0 68
0 2 4 161160 22496 886304 0 0 0 58856 439 479 3 39 0 58
0 2 4 115652 22540 930336 0 0 0 44032 355 523 2 32 0 66
0 2 4 68036 22584 976416 0 0 0 46080 426 699 6 32 0 62
1 1 4 22548 22628 1020476 0 0 0 44028 366 590 15 29 0 56
2 2 4 23032 22672 1019420 0 0 0 42012 386 1082 40 36 0 24
0 2 4 24272 20772 1019388 0 0 0 45116 360 779 16 36 0 48
1 1 184 23652 16948 1022416 0 0 0 33968 365 446 20 30 0 50
0 2 184 23280 16668 1022620 0 0 0 50188 369 505 3 35 0 62
0 2 184 24520 16688 1020540 0 4 0 44036 376 458 9 36 0 55
0 2 184 27868 16632 1022072 0 0 0 25908 459 441 5 19 0 76
1 1 184 23652 6796 1036996 0 0 0 37820 386 472 3 30 0 67
0 0 184 24520 6084 1037356 0 0 0 16580 342 424 4 15 1 80
0 0 184 24644 6084 1037356 0 0 0 0 294 374 1 0 99 0
(TERMINAL 2) user@box:~%dd if=/dev/zero of=/path/to/parition/on/SATA/disk/file bs=1024 count=1000000
1000000+0 records in
1000000+0 records out
1024000000 bytes (1.0 GB) copied, 22.2838 s, 46.0 MB/s

Sata was a bit faster, as expected.

2) athcool on
a) dd to IDE
(TERMINAL 1) user@box:~% vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
2 0 184 119536 7040 942204 0 0 119 2047 300 740 8 3 82 7
0 0 184 119536 7040 942204 0 0 0 0 290 711 4 0 96 0
1 2 184 103292 7092 958828 0 0 16 4496 413 685 2 13 82 3
0 1 184 67828 7124 993432 0 0 0 46884 612 1149 2 30 0 68
0 1 184 54188 7136 1006756 0 0 0 13312 552 878 2 12 0 86
0 1 184 22908 7196 1036576 0 0 0 62472 447 1007 7 50 0 43
0 1 184 24644 7224 1034272 0 0 0 24428 459 739 1 27 0 72
0 3 184 25760 7236 1034740 0 0 0 4392 499 732 2 10 0 88
1 3 184 23652 7284 1036484 0 0 0 42900 536 977 3 39 0 58
1 4 184 25140 7308 1034448 0 0 0 41144 470 861 3 19 0 78
0 2 184 24636 7340 1034084 0 0 12 33816 466 797 4 26 0 70
0 2 184 25256 7340 1034084 0 0 0 0 447 605 2 3 0 95
0 2 184 22904 7424 1035360 0 0 4 73032 466 848 6 58 0 36
0 2 184 23272 7452 1036132 0 0 0 23308 458 786 3 27 0 70
0 2 184 24144 7500 1035644 0 0 0 46364 478 800 7 35 0 58
0 2 184 25132 7560 1034492 0 0 0 23356 441 673 2 16 0 82
0 2 184 25752 7560 1034492 0 0 0 0 502 728 1 0 0 99
0 1 184 23768 7632 1034748 0 0 0 74820 407 778 6 57 0 37
0 2 184 23644 7672 1035388 0 0 0 41016 465 829 5 30 0 65
0 2 184 23272 7712 1036284 0 0 0 39216 448 744 3 31 0 66
0 1 184 23148 7752 1035900 0 0 0 37084 535 1120 3 29 0 68
0 1 184 23024 7800 1035420 0 0 0 46112 435 724 3 34 0 63
0 1 184 23024 6900 1035472 0 0 0 34832 480 737 5 24 0 71
1 1 184 23024 6660 1036344 0 0 0 28956 450 759 2 30 0 68
1 1 184 24016 6592 1035540 0 0 0 37108 483 873 2 27 0 71
0 1 184 23396 6636 1036104 0 180 0 46644 420 874 6 34 0 60
1 0 196 23148 6668 1036156 0 0 0 37896 473 812 5 29 0 66
0 1 196 23272 6712 1035412 0 0 0 45064 409 709 2 34 0 64
1 1 196 23148 6720 1037232 0 0 0 356 471 637 2 7 0 91
0 2 196 23648 6744 1036236 0 0 0 48400 433 893 3 34 0 63
0 1 196 23396 6276 1036672 0 0 0 46100 462 1001 4 33 0 63
0 0 196 24016 6280 1036672 0 0 0 4 445 586 1 2 75 22
0 0 196 24388 6280 1036672 0 0 0 0 358 475 1 3 96 0
0 0 196 24388 6280 1036672 0 0 0 0 272 362 1 0 99 0
(TERMINAL 2) user@box:~% dd if=/dev/zero of=/path/to/parition/on/IDE/disk/file bs=1024 count=1000000
1000000+0 records in
1000000+0 records out
1024000000 bytes (1.0 GB) copied, 28.1283 s, 36.4 MB/s

Hello degraded performace! 44.7Mb/s -> 36.4MB/s. This is a 18.57% drop. Still I consider it quite acceptable for a desktop pc.

a) dd to SATA
(TERMINAL 1) user@box:~% vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
2 0 196 1031508 5284 43612 0 0 94 2389 310 715 8 3 77 12
0 0 196 1031508 5284 43612 0 0 0 0 312 662 5 0 95 0
1 0 196 966284 5284 107512 0 0 0 63484 343 457 6 48 15 31
0 1 196 959588 5284 114240 0 0 0 7168 403 694 4 6 0 90
0 1 196 952272 5284 121408 0 0 0 7168 371 610 4 8 0 88
0 1 196 944956 5284 128572 0 0 0 7164 420 478 2 6 0 92
1 1 196 918544 5324 151464 0 0 376 22652 429 1713 18 27 0 55
0 2 196 917924 5324 152488 0 0 0 1048 416 649 2 3 0 95
0 2 196 918048 5324 152488 0 0 0 16 392 540 0 0 0 100
0 2 196 917552 5336 152648 0 0 172 20 435 780 2 0 0 98
0 2 196 917676 5336 152648 0 0 0 0 372 491 0 0 0 100
0 2 196 917800 5344 152648 0 0 0 60 404 559 3 0 0 97
0 2 196 917924 5344 152648 0 0 0 20 380 620 2 1 0 97
0 2 196 918172 5344 152648 0 0 0 28 416 966 6 1 0 93
0 2 196 918296 5344 152648 0 0 0 16 369 356 2 0 0 98
0 2 196 918420 5344 152648 0 0 0 16 401 384 0 1 0 99
0 1 196 850840 5360 219204 0 0 0 66884 467 696 3 51 0 46
0 1 196 845384 5368 224324 0 0 0 5136 419 520 3 1 0 96
0 1 196 836952 5368 232512 0 0 0 8188 385 742 4 5 0 91
0 1 196 831744 5368 237632 0 0 0 5120 426 489 0 1 0 99
0 1 196 825420 5368 243776 0 0 0 6144 422 600 0 1 0 99
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
1 2 196 819064 5368 245824 0 0 0 2096 417 1427 29 6 0 65
0 2 196 823560 5368 245824 0 0 0 20 494 1913 16 4 0 80
0 2 196 823808 5376 245824 0 0 0 28 480 1719 8 2 0 90
0 1 196 758336 5384 310328 0 0 0 64800 423 1204 24 53 0 23
[snip]
0 2 196 104236 5628 954752 0 0 0 8 405 745 2 2 0 96
0 2 196 43600 5640 1013984 0 0 0 59740 453 815 4 44 0 52
0 2 196 29712 5640 1027300 0 0 0 13320 403 758 3 5 0 92
0 2 196 23892 5640 1032852 0 0 0 9220 430 693 4 4 0 92
0 1 196 22776 3892 1035820 0 0 0 7184 402 728 5 1 0 94
0 1 196 22776 3892 1035820 0 0 0 0 451 1172 5 3 0 92
0 1 196 22776 3892 1035820 0 0 0 0 386 813 2 1 0 97
0 1 196 22776 3896 1035820 0 0 0 4 412 385 0 0 0 100
0 1 196 22776 3896 1035820 0 0 0 4 358 320 0 0 0 100
0 1 196 25380 3896 1032748 0 0 0 0 416 722 7 1 0 92
0 1 196 25504 3904 1032748 0 0 0 16 365 404 2 2 0 96
0 1 196 25628 3904 1032748 0 0 0 0 396 471 1 1 0 98
0 1 196 25876 3904 1032748 0 0 0 0 364 526 6 0 0 94
0 0 196 26992 3912 1032748 0 0 0 968 395 1288 14 3 55 28
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 1 196 26992 3912 1032748 0 0 0 4 323 1412 13 1 86 0
0 0 196 26992 3920 1032748 0 0 0 12 379 1755 16 1 83 0
(TERMINAL 2) user@box:~%dd if=/dev/zero of=/path/to/parition/on/SATA/disk/file bs=1024 count=1000000
1000000+0 records in
1000000+0 records out
1024000000 bytes (1.0 GB) copied, 114.792 s, 8.9 MB/s

What about that!!! 46Mb/s -> 8.9Mb/s That’s an incredible 80% percent performance loss! I/O wait is always maxed at 90-100% which makes the machine totally unresponsive. I had to snip the output of vmstat because it is huge. It’s more than 140lines while all the others were at max 36 (athcool on, IDE). If anyone wants it I can surely upload it here.

I don’t think that’s what the programmer of athcool had in mind when he was talking about degraded performance…I think this is a bug. I can accept a 20% loss but not an 80% loss of performance. By the way, these tests were performed on ext3, but the same results appear with reiserfs as well.

This “bug” took me a while to figure out. I had my sata disk crawling for a long time before I thought of disabling athcool (yeah yeah I know it should have been the first thing to do…). I initially thought on posting the “bug” to the Gentoo bugzilla but while searching it I came up with this:
sys-power/athcool causes massive filesystem corruption; upstream was informed but did not respond. As far as I can tell Gentoo developers think that since there is a warning there is no extra reason that this package should be masked or whatever.

Dear Internets,
Is there anyone else who can confirm the same behavior of athcool with sata controllers ? I don’t have another sata controller to test, but if someone uses a different sata module, a test like the one I performed would show us whether it’s a sata_sil problem, so that I should report it to the kernel maintainers or an athcool problem, so that we should at least fill a new bug at the Gentoo bugzilla to ask the developers to hardmask the package.

Filed by kargig at 10:47 under Gentoo,Linux
Tags: athcool, bug, bug-report, bugzilla, dd, ext3, Gentoo, IDE, Linux, performance, powesaving, sata, sata_sil, vmstat
No Comments | 8,962 views