Re: 2.5.59-mm5

Ed Tomlinson
2003-01-26T01:43:09Z

On January 25, 2003 05:33 pm, Andrew Morton wrote:
> Ed Tomlinson <tomlins@cam.org> wrote:
> > On January 25, 2003 12:41 pm, Andrew Morton wrote:
> > > Ed Tomlinson <tomlins@cam.org> wrote:
> > > > Hi Andrew,
> > > >
> > > > I am seeing a strange problem with mm5. This occurs both with and
> > > > without the anticipatory scheduler changes. What happens is I see
> > > > very high system times and X responds very very slowly. I first
> > > > noticed this when switching between folders in kmail and have seen it
> > > > rebuilding db files for squidguard. Here is what happened during the
> > > > db rebuild (no anticipatory ioscheduler):
> > >
> > > Could you please try reverting the reiserfs changes?
> > >
> > > http://www.zip.com.au/~akpm/linux/patches/2.5/2.5.59/2.5.59-mm5/broken-
> > >out/ reiserfs-readpages.patch
> > >
> > > and
> > >
> > > http://www.zip.com.au/~akpm/linux/patches/2.5/2.5.59/2.5.59-mm5/broken-
> > >out/ reiserfs_file_write.patch
> >
> > Reverting reiserfs_file_write.patch seems to cure the interactivity
> > problems. I still see the high system times but they in themselves are
> > not a problem. Reverting the second patch does not change the situation.
> > I am currently running with reiserfs_file_write.patch removed - so far so
> > good.
>
> Well, high system time _is_ a problem, isn't it? Do you always see that?
>
> Or perhaps userspace monitoring tools are confusing I/O wait with CPU
> busyness. Does a revert of
>
> http://www.zip.com.au/~akpm/linux/patches/2.5/2.5.59/2.5.59-mm5/broken-out/
>buffer-io-accounting.patch
>
> make the numbers look different? If so, then it's a procps bug...
>
> WRT the excessive copy_foo_user() times: I shall forward your initial email
> to Oleg, thanks.

The excessive copy_foo_user times are still there with Oleg (and Chris's) patch
removed. Here is what I see doing:

"apt-get install --reinstall squidguard chastity-list"

(with file_write from my first message)
55091 default_idle 1377.2750
62640 __copy_from_user_ll 1204.6154
33595 __copy_to_user_ll 646.0577

(without file_write)
40259 __copy_from_user_ll 774.2115
18735 default_idle 468.3750
21524 __copy_to_user_ll 413.9231
386 system_call 8.0417
428 current_kernel_time 7.1333
988 established_get_next 6.8611
60 ide_outb 5.0000
509 reiserfs_prepare_write 4.2417
100 get_offset_tsc 4.1667
38 syscall_call 3.4545
159 fget 2.4844
279 radix_tree_lookup 2.2500
61 init_journal_hash 1.9062
68 task_vsize 1.8889
105 mark_page_accessed 1.7500
366 find_lock_page 1.7264
48 delay_tsc 1.7143
89 block_prepare_write 1.7115
237 update_atime 1.6458
32 fput 1.6000
90 unlock_page 1.5000
210 inode_update_time 1.3816
108 sys_pwrite64 1.3500
16 ide_inb 1.3333
78 mark_buffer_dirty 1.3000
192 reiserfs_wait_on_write_block 1.2632
93 handle_IRQ_event 1.2237
76 fault_in_pages_readable 1.1875
4 reiserfs_check_lock_depth 1.0000

So removing file_read seems to have reduced the copy_foo_user() issue but
has not removed it.

Using a vmstat hacked to show iowait with the above running...

oscar% vmstat -a 5

procs memory (mB) swap io system cpu
r b w swpd free inact act si so bi bo in cs us sy io id
3 0 0 42 6 13 434 0 3 36 69 1061 61 25 3 1 71
5 0 0 42 4 15 434 0 0 1189 893 1184 18253 28 11 10 51
4 0 0 42 5 8 440 0 66 353 274 1070 7874 74 7 10 9
6 0 0 42 6 9 438 0 0 468 343 1081 2936 93 7 0 0
5 0 0 46 4 5 444 0 714 1453 976 1147 8891 87 13 0 0
4 0 0 51 5 1 447 0 1086 626 1877 1279 23445 57 43 0 0
4 1 1 52 4 3 446 0 290 615 1206 1219 22018 68 32 0 0
6 0 0 53 8 10 434 0 82 690 1020 1141 14962 59 41 0 0
10 0 0 53 36 14 403 0 0 2 599 1206 1988 85 15 0 0
5 0 0 53 27 9 417 0 0 35 94 1072 1269 94 6 0 0
5 0 0 53 31 11 411 0 0 188 761 1089 2401 88 12 0 0
8 0 0 53 26 11 416 0 0 1 298 1052 9013 42 28 3 27
7 0 0 53 25 11 417 0 0 0 22 1021 574 38 62 0 0
10 0 0 53 24 11 418 0 0 0 34 1014 546 53 47 0 0
11 0 0 53 23 11 419 0 0 0 1814 1142 634 43 57 0 0
9 0 0 53 22 11 421 0 0 2 39 1019 556 40 60 0 0
13 0 0 53 20 10 423 0 0 0 32 1031 1183 51 47 0 2
9 0 0 53 18 10 425 0 0 0 1946 1083 560 36 64 0 0
9 0 0 53 17 10 426 0 0 0 28 1016 575 38 62 0 0
10 0 0 53 16 10 427 0 0 0 47 1022 560 52 48 0 0
9 0 0 53 15 10 428 0 0 0 36 1015 540 28 72 0 0
9 0 0 53 14 10 429 0 0 0 27 1023 603 48 52 0 0
8 0 0 53 13 10 430 0 0 0 36 1019 536 48 52 0 0
9 0 0 53 12 10 431 0 0 0 367 1029 539 36 64 0 0
11 0 0 53 11 10 432 0 0 0 1785 1112 587 32 68 0 0
10 0 0 53 11 10 433 0 0 0 58 1030 610 75 25 0 0
10 0 0 53 10 10 433 0 0 0 38 1037 599 67 33 0 0
12 0 0 53 10 10 434 0 0 0 34 1056 679 81 19 0 0
14 0 0 53 10 10 434 26 0 26 44 1059 647 42 58 0 0
13 0 0 53 9 10 435 0 0 0 45 1050 686 56 44 0 0
10 0 0 53 9 10 435 0 0 0 585 1083 678 59 41 0 0
procs memory (mB) swap io system cpu
r b w swpd free inact act si so bi bo in cs us sy io id
9 0 1 53 8 10 435 0 0 0 2518 1200 727 48 52 0 0
10 0 0 53 8 10 436 0 0 0 43 1065 660 38 62 0 0
11 0 0 53 7 10 437 0 0 0 39 1044 661 29 71 0 0
9 0 0 53 6 9 438 0 0 0 196 1063 676 44 56 0 0
9 0 0 53 5 10 438 0 0 0 732 1169 681 27 73 0 0
6 4 0 53 4 10 440 0 0 0 633 1121 1987 52 48 0 0
10 0 0 53 10 12 431 0 0 2 3294 1203 8145 54 46 0 0
11 0 0 53 24 17 412 0 0 0 806 1133 686 60 40 0 0

Unless its an accounting error, its not iowait (confirmed on a nonbusy system
too). There is no change with or with out the io_schedule() changed back to
schedule().

Ed Tomlinson