Messages in this thread | | | Date | Sun, 02 Jul 2000 23:24:32 +1000 | From | Andrew Morton <> | Subject | Re: Low Latency |
| |
Kai Henningsen wrote: > > So: IMAO, the right way is (1) fix those areas where you can see that > there is obviously a local problem
Yes.
Linus is okay with the addition of a few tasteful and carefully designed conditional_reschedule() calls to work around this issue in 2.4.
Robert & co are okay with an _occasional_ scheduling delay - with a sufficiently powerful and correctly set up machine, it could well be that a tiny subset of the low-latency patch will fix their problems.
So the way forward is to identify the worst areas where these stalls are occuring and try to cleanly fix them. Surely?
I've done a few measurements on a 2x500MHz machine. Both of the attached files show results across a kernel build. All times (min, max, avg, total) are in microseconds.
syscalls.txt shows the amount of wall-clock time a CPU spent in a particular system call.
copy_usr.txt shows the elapsed time which the system spent in copy_to_user and copy_from_user. Again, this is wall-clock time, so any interrupt which occurs will add to these times.
These numbers aren't particularly useful yet, but they can be improved when I understand the problem better.
They do show that the longest time that was ever spent in copy_*_user() was 570 uSecs, which would suggest that this was simply a convenient place for the conditional_reschedule rather than being a CPU pig in itself.
They also show that sys_brk can sometimes take a very long time. I really don't see why this should be, as at no time during the build did I have less than 50Mbytes of free memory.
I'll try stopping & restarting the instrumentation within schedule(). This will give the _real_ scheduling latency figures. (eek. That's going to take a lot of coding. Several days worth).
Does anyone actually _know_ where the problems are occurring?
Has anyone incrementally applied the low-latency patch to see which fixes are the most effective?
Robert, Paul: test cases, please. Can you please tell me what system activity causes the most problems? Is there a particular system activity or application which will reliably kill scheduling latency? If I can't reproduce it here will you be able to apply a truckload of patches (against 2.4.0) so we can get to the bottom of it?
Generally speaking, can we please all stop shouting at each other and, umm, y'know, do some technical stuff? nr_times min max avg total
start 0162:0 -> stop 0162:0 13 70.37 36867305.82 3293742.81 42818656.54 nanosleep start 0003:0 -> stop 0003:0 135604 .56 15004292.07 2476.55 335830746.49 read start 0142:0 -> stop 0142:0 1173 5.91 9447280.43 196672.32 230696638.97 select start 0114:0 -> stop 0114:0 1186 .73 3092356.14 14327.26 16992136.44 wait4 start 0001:0 -> stop 0001:0 2345 193.44 2461665.00 3525.92 8268285.36 exit start 0179:0 -> stop 0179:0 8 33.84 827280.09 231713.72 1853709.82 sigsuspend start 0036:0 -> stop 0036:0 7 1096.74 552073.82 94707.80 662954.64 sync start 0011:0 -> stop 0011:0 10263 4.86 209516.45 321.38 3298342.53 execve start 0004:0 -> stop 0004:0 57305 .51 157715.44 198.77 11391008.91 write start 0045:0 -> stop 0045:0 445810 .36 154005.14 46.65 20798458.34 brk start 0106:0 -> stop 0106:0 26645 3.58 131423.69 62.20 1657500.39 newstat start 0107:0 -> stop 0107:0 13252 3.99 115579.30 465.08 6163361.26 newlstat start 0006:0 -> stop 0006:0 89874 .36 94709.37 18.07 1624571.03 close start 0091:0 -> stop 0091:0 6185 3.90 67443.46 69.94 432613.09 munmap start 0141:0 -> stop 0141:0 11893 1.00 64348.94 577.40 6867067.92 getdents start 0163:0 -> stop 0163:0 451 7.83 56350.26 217.21 97963.51 mremap start 0005:0 -> stop 0005:0 91666 4.34 52861.29 78.71 7215900.72 open start 0010:0 -> stop 0010:0 841 12.66 34119.20 4257.77 3580788.44 unlink start 0190:0 -> stop 0190:0 458 121.83 14801.81 476.59 218279.86 vfork start 0090:0 -> stop 0090:0 21435 3.81 3003.70 23.05 494310.97 old_mmap start 0174:0 -> stop 0174:0 12821 1.63 2573.70 9.20 118002.73 sigaction start 0108:0 -> stop 0108:0 143415 1.95 1905.15 5.58 800491.94 newfstat start 0002:0 -> stop 0002:0 474 280.81 1871.95 690.97 327522.48 start 0140:0 -> stop 0140:0 18254 .71 1693.63 4.99 91223.08 start 0033:0 -> stop 0033:0 4632 3.93 1650.84 20.16 93419.69 start 0136:0 -> stop 0136:0 2141 .89 1622.48 5.97 12802.72 start 0102:0 -> stop 0102:0 76 2.87 1455.19 114.84 8728.43 start 0183:0 -> stop 0183:0 891 5.17 882.27 31.21 27815.30 start 0013:0 -> stop 0013:0 827 .22 824.68 5.43 4495.74 start 0020:0 -> stop 0020:0 3414 .28 716.18 3.74 12775.20 start 0064:0 -> stop 0064:0 444 .93 630.36 8.55 3799.04 start 0019:0 -> stop 0019:0 222 .69 587.30 9.52 2115.35 start 0077:0 -> stop 0077:0 396 5.97 573.17 18.57 7357.43 start 0175:0 -> stop 0175:0 61629 1.49 534.16 3.19 197253.19 start 0024:0 -> stop 0024:0 441 .87 411.62 2.62 1157.10 start 0042:0 -> stop 0042:0 860 13.14 361.09 98.22 84477.00 start 0038:0 -> stop 0038:0 7 173.26 350.43 250.61 1754.33 start 0055:0 -> stop 0055:0 6201 .61 335.95 3.13 19431.05 start 0012:0 -> stop 0012:0 5517 2.35 286.69 5.84 32225.35 start 0041:0 -> stop 0041:0 1355 .91 274.12 8.44 11441.32 start 0054:0 -> stop 0054:0 528 .77 240.24 27.84 14704.30 start 0063:0 -> stop 0063:0 553 .97 201.58 15.87 8780.12 start 0075:0 -> stop 0075:0 351 3.87 190.89 8.37 2940.38 start 0065:0 -> stop 0065:0 440 .50 185.62 1.88 830.60 start 0047:0 -> stop 0047:0 441 .31 167.92 1.71 758.69 start 0125:0 -> stop 0125:0 3479 3.02 142.88 18.28 63616.59 start 0078:0 -> stop 0078:0 396 1.83 104.46 14.27 5653.10 start 0040:0 -> stop 0040:0 1 70.48 70.48 70.48 70.48 start 0066:0 -> stop 0066:0 24 32.42 69.86 52.27 1254.73 start 0015:0 -> stop 0015:0 19 3.06 60.51 17.98 341.66 start 0122:0 -> stop 0122:0 494 3.22 54.50 16.16 7983.98 start 0119:0 -> stop 0119:0 1545 .74 38.63 7.79 12044.13 start 0027:0 -> stop 0027:0 135 1.36 35.71 12.70 1715.26 start 0037:0 -> stop 0037:0 1 31.51 31.51 31.51 31.51 start 0076:0 -> stop 0076:0 350 4.59 21.72 9.36 3277.34 start 0057:0 -> stop 0057:0 13 3.33 20.13 5.96 77.59 start 0023:0 -> stop 0023:0 24 5.25 18.07 10.37 248.91 start 0081:0 -> stop 0081:0 24 5.72 17.80 10.67 256.29 start 0080:0 -> stop 0080:0 40 5.17 16.33 9.17 366.90 start 0182:0 -> stop 0182:0 4 8.53 12.21 10.00 40.04 start 0043:0 -> stop 0043:0 26 4.10 10.59 6.27 163.17 start 0046:0 -> stop 0046:0 24 2.81 10.18 5.35 128.59 start 0030:0 -> stop 0030:0 1 8.02 8.02 8.02 8.02 start 0133:0 -> stop 0133:0 4 3.94 6.10 4.60 18.41 start 0049:0 -> stop 0049:0 442 .28 3.14 .31 137.64 start 0060:0 -> stop 0060:0 21 .25 2.17 1.00 21.11 start 0050:0 -> stop 0050:0 439 .27 .70 .28 126.74
nr_times min max avg total
pipe.c:97 -> pipe.c:97 45522 .27 574.81 90.66 4127268.07 pipe.c:195 -> pipe.c:195 45478 .27 603.22 80.32 3652920.80 filemap.c:2518 -> filemap.c:2518 55059 .27 571.44 49.63 2732940.67 stat.c:114 -> stat.c:114 173223 .25 222.73 .42 73837.04 exec.c:227 -> exec.c:227 183500 .27 268.69 .35 65460.86 readdir.c:185 -> readdir.c:185 122832 .26 86.13 .36 45271.27 signal.c:684 -> signal.c:684 58938 .18 93.24 .26 15989.74 sys_i386.c:102 -> sys_i386.c:102 21386 .21 222.89 .52 11197.06 signal.c:720 -> signal.c:720 30725 .19 83.39 .26 8081.66 n_tty.c:913 -> n_tty.c:913 1808 .28 42.42 3.28 5935.69 read_write.c:107 -> read_write.c:107 18218 .20 51.80 .29 5411.32 signal.c:1075 -> signal.c:1075 12752 .20 68.96 .38 4907.51 signal.c:1068 -> signal.c:1068 12752 .20 52.59 .32 4162.93 sys.c:968 -> sys.c:968 494 .80 32.63 7.10 3510.72 n_tty.c:255 -> n_tty.c:255 2837 .26 9.42 .91 2597.98 dcache.c:990 -> dcache.c:990 885 .36 13.34 1.76 1558.34 iovec.c:91 -> iovec.c:91 439 .27 60.92 1.10 485.22 sys.c:1137 -> sys.c:1137 392 .27 3.65 1.19 468.70 sys_i386.c:38 -> sys_i386.c:38 859 .18 2.15 .46 401.77 tty_ioctl.c:401 -> tty_ioctl.c:401 161 .24 4.89 2.40 387.69 time.c:118 -> time.c:118 396 .19 77.61 .93 369.31 sys.c:1069 -> sys.c:1069 350 .30 21.00 .99 349.43 sys.c:1058 -> sys.c:1058 350 .26 2.54 .80 281.74 tcp.c:901 -> tcp.c:901 111 .28 19.61 1.84 204.83 pty.c:158 -> pty.c:158 415 .28 2.34 .46 195.14 socket.c:1476 -> socket.c:1476 77 .26 4.12 1.31 101.36 uid16.c:122 -> uid16.c:122 40 .36 5.02 2.00 80.34 timer.c:842 -> timer.c:842 24 .22 10.89 2.03 48.80 uid16.c:137 -> uid16.c:137 24 .61 3.85 2.02 48.57 generic.c:107 -> generic.c:107 1 46.91 46.91 46.91 46.91 ide.c:2592 -> ide.c:2592 12 1.16 8.81 3.13 37.58 tty_ioctl.c:159 -> tty_ioctl.c:159 47 .24 2.86 .77 36.43 time.c:122 -> time.c:122 26 .19 2.75 1.36 35.54 timer.c:814 -> timer.c:814 36 .18 2.89 .84 30.39 sys.c:749 -> sys.c:749 26 .40 2.94 1.06 27.64 tty_io.c:1491 -> tty_io.c:1491 27 .19 2.26 .55 15.06 ide.c:2567 -> ide.c:2567 12 .71 2.25 1.18 14.19 signal.c:103 -> signal.c:103 13 .41 1.77 .86 11.29 socket.c:219 -> socket.c:219 9 .39 2.25 .93 8.44 tty_io.c:1501 -> tty_io.c:1501 9 .21 .57 .25 2.27
| |