This is the second try, the last mail was too long.
Hello LiS-Comunity,
I tested with LiS-2.17-R on a Intel (*86) mono and two-processormachine.
The Linux version is Suse SLES8.
I called the strtst and (depending on amount of debug-loggings, type of
machine and other conditions, which I do not know,) the test sometimes
runs well, but mostly failed at one of "band_tests".
On the two processor machine sometimes it was not possible to unload
streams and I had to reboot the machine.
Looking at the logging in messages, I had the feeling, that the
appropriate service routines were not called in time.
I changed the last option, asked in the Configure phase, to n and added
some debugging-instructions to prove, if this is correct. (You can find
the extensions at the end as diff)
To debug in this way is not nice, because:
- Adding or removing printk-instructions does change the behaviour to
any direction: worse or better.
- You can never be sure, that some important entries are not lost.
So I can not present "reasonable traces" from all the errors, that
happened and can reproduce the same error only with some luck.
In the appended Traces, which are reasonable good to read, I added also
remarks to bring your attention to the points, which seemed important
for me.
The result:
The message sent down is not processed in time. Generally it takes a
long time until lis_thread_runqueues is waked up.
In worst cases it took up to 0,22 seconds from lis_up to scheduling of
lis_thread_runqueues!
Guess something is wrong with the priority of this LiS-RunQ-process.
Dont know how to prove or make it better.
I grepped for the keyword mregparm in all files under /usr/src/ to
exclude the mentioned problems with parameter passing. Did find it only
in comments.
So please can You give me some proposals how to go on with that problem.
May be, You know more about this problem.
Other proposals are also welcome, because I am new at Linux.
I also tested with other LiS-versions:
LiS-2.16:
No troubles until now. There lis_run_queues is called mostly direct, so
there is no delay.
But we have to use LiS-2.17/18, because we need the feature "per-driver
locking option in LiS"
LiS-2.17-H:
The same problems as in LiS-2.17-R. Additional the two processor machine
panics. Also some minor problems.
I changed lis_setqsched at the LiS-2.17* versions (see switch
CALL_DIRECT in linux-mdep.c) and called lis_run_queues in most cases
directly. Strtst did not fail.
By the way: strtst lasts 161 seconds in old way and 95 seconds with
direct call.
This is my emergency exit (but do not feel good about):
Changing to direct call, will change the behaviour and will be a work
around for a while until going into strong tests.
But it is not the real solution. It will not work, if in
interruptcontext, lis_in_syscall==1, can_call=0.
Additional Dave changed his strategy away from direct call and I do not
know the reasons why and if this flags: lis_in_syscall, can_call will be
set correct in this and future versions of LiS, since they are no more
necessary for his new strategy in lis_setqsched.
What do You think about?
best regards
Klaus Golbach
******************** TRACES **************************************
:
: Linux STREAMS Subsystem loading...
REMARK: To know something about the used Linux version, there are some
debug-prints in lis_init_module
: lis_init_module. Following defines set:
: __SMP__
: KERNEL_2_3
: NOT KERNEL_2_5
: KERNEL_2_1
: NOT KERNEL_2_2
: NOT KERNEL_2_4
: LINUX
: __KERNEL__
: CONFIG_MAX_USER_RT_PRIO:100 MAX_USER_RT_PRIO:100 MAX_RT_PRIO:100
MAX_PRIO:140
: STREAMS module "connld" registered (loadable), id 1
: STREAMS module "ip_strms" registered, id 2
: STREAMS module "pipemod" registered (loadable), id 3
: STREAMS module "relay" registered, id 4
: STREAMS module "relay2" registered, id 5
: STREAMS module "timod" registered (loadable), id 6
: STREAMS module "tirdwr" registered (loadable), id 7
: STREAMS driver "clone-drvr" registered, major 231
: STREAMS driver "fifo" registered, major 232
: STREAMS driver "fifo" registered, major 233
: STREAMS driver "loop-around" registered, major 234
: mknod /dev/loop_clone: OK
: mknod /dev/loop.1: OK
: mknod /dev/loop.2: OK
: mknod /dev/loop.9: OK
: mknod /dev/loop.255: OK
: STREAMS driver "mini-mux" registered, major 235
: STREAMS driver "printk" registered, major 236
: Added initial autopush entries.
: LiS-RunQ-2.17.R running on CPU 0 pid=5611
: LiS-RunQ-2.17.R running on CPU 1 pid=5612
: lis_thread_runqueues After schedule. LiS-RunQ with pid:5612 running on
cpu: 1 should be on cpu:1
: Linux STREAMS Subsystem ready.
: Copyright (c) 1997-2003 David Grothe, et al, http://www.gcom.com
: Major device number 252.
: Version 2.17.R 07/2/04. Compiled for kernel version 2.4.19-64GB-SMP.
: Using <linux/poll.h> <LiS/include/sys/stropts.h>
: ==================================================================
: lis_thread_runqueues After schedule. LiS-RunQ with pid:5611 running on
cpu: 0 should be on cpu:0
: strtst:
: Begin STREAMS test
........
REMARK: Here starts the test, which failed!
: strtst:
: band_test: write band 1, 2, 3; read band 3, 2, 1
: lis_freeb: (mblk) bp=0xd7f11a60 dp=0xd7f11a84
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_head_get([EMAIL PROTECTED]/++2/1) "loop(234,1)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11a60 dp=0xd7f11a84(intl) from mblk
/usr/src/LiS-2.17/head/head.c 1748
: rptr=0xd7f11aa0 wptr=0xd7f11aa0 size=19
: strputmsg: stream loop(234,1): send 0/19 ctl/data bytes downstream to
loop
: strputmsg: q = 0xd986f97c, msg = 0xd7f11a60
: putnext: M_DATA from "str_wput" to "loop" size 64
: q=d986f97c, mp=d7f11a60, mp->b_rptr=d7f11aa0, wptr=d7f11ab3
: putnext: M_DATA from "loop" to "str_rput" size 64
: q=d986f2c0, mp=d7f11a60, mp->b_rptr=d7f11aa0, wptr=d7f11ab3
: 215131:CPU0 in lis_strrput() head/head.c #3300 -- d82ed280 0xd7f11a60
: lis_strrput: loop(234,2) queueing M_DATA
: 215150:CPU0 in lis_qenable() head/queue.c #1285 -- cb7bd860 0x71
: lis_head_get([EMAIL PROTECTED]/++2/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:2 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "loop(234,1)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:3 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "loop(234,1)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11e60 dp=0xd7f11e84(intl) from mblk
/usr/src/LiS-2.17/head/head.c 1748
: rptr=0xd7f11ea0 wptr=0xd7f11ea0 size=19
: strputmsg: stream loop(234,1): send 0/19 ctl/data bytes downstream to
loop
: strputmsg: q = 0xd986f97c, msg = 0xd7f11e60
: putnext: M_DATA from "str_wput" to "loop" size 64
: 1 lis_thread_runqd7f11e60, mp->b_rptr=d7f11ea0, wptr=d7f11eb3
: 1 lis_thread_runqd7f11e60, mp->b_rptr=d7f11ea0, wptr=d7f11eb3
: lis_malloc: 0xd8a5f540: /usr/src/LiS-2.17/head/queue.c #426, size=32
: putnext: M_DATA from "loop" to "str_rput" size 64
: q=d986f2c0, mp=d7f11e60, mp->b_rptr=d7f11ea0, wptr=d7f11eb3
: q=d986f2c0, mp=d7f11e60, mp->b_rptr=d7f11ea0, wptr=d7f11eb3
: 215253:CPU1 in queuerun() head/stream.c #275 -- cb7bd860 0xd82ed280
: 215259:CPU1 in lis_strrsrv() head/head.c #3247 -- d82ed280 0x0
: 215277:CPU1 in lis_process_rput() head/head.c #2946 -- cb7bd860
0xd7f11a60
: 215283:CPU1 in lis_process_rput() head/head.c #2948 -- cb7bd860
0xd7f11a60
: 215292:CPU1 in lis_process_rput() head/head.c #2955 -- d82ed280
0xd7f11a60
: lis_process_rput: received M_DATA (0) from "loop" on stream
loop(234,2) size 64
: 215298:CPU1 in lis_process_rput() head/head.c #3008 -- d82ed280
0xd7f11a60
: 215304:CPU1 in lis_process_rput() head/head.c #3015 -- d7f11a60 0x0
: 215315:CPU1 in lis_process_rput() head/head.c #3208 -- d7f11a60 0x0
: 215333:CPU1 in lis_strrsrv() head/head.c #3264 -- d82ed280 0x0
: 215342:CPU1 in lis_strrsrv() head/head.c #3268 -- d82ed280 0x0
: 215353:CPU1 in queuerun() head/stream.c #292 -- cb7bd860 0x4070
: 215359:CPU1 in queuerun() head/stream.c #309 -- cb7bd860 0x70
: lis_head_put([EMAIL PROTECTED]/--1/1) "loop(234,2)" {head/[EMAIL PROTECTED]
REMARK: Last time lis_thread_runqueues was processed.
After next entry it waits at the sema for a new trigger.
: CPU1 lis_thread_runqueues wait at sema. lis_runq_req_cnt:0 ; processed
lis_run_queues 0 ticks
: 215378:CPU0 in lis_strrput() head/head.c #3300 -- d82ed280 0xd7f11e60
: lis_strrput: loop(234,2) queueing M_DATA
: 215397:CPU0 in lis_qenable() head/queue.c #1285 -- cb7bd860 0x71
: lis_head_get([EMAIL PROTECTED]/++2/1) "loop(234,2)" {head/[EMAIL PROTECTED]
REMARK: Here the second time lis_thread_runqueues is triggered to run,
but does not.
Entry of first trigger is lost.
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:2 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "loop(234,1)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:3 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "loop(234,1)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11860 dp=0xd7f11884(intl) from mblk
/usr/src/LiS-2.17/head/head.c 1748
: rptr=0xd7f118a0 wptr=0xd7f118a0 size=19
: strputmsg: stream loop(234,1): send 0/19 ctl/data bytes downstream to
loop
REMARK: Here a message 0xd7f11860 is sent down
: strputmsg: q = 0xd986f97c, msg = 0xd7f11860
: putnext: M_DATA from "str_wput" to "loop" size 64
: q=d986f97c, mp=d7f11860, mp->b_rptr=d7f118a0, wptr=d7f118b3
: lis_malloc: 0xd7c6bf20: /usr/src/LiS-2.17/head/queue.c #426, size=32
: putnext: M_DATA from "loop" to "str_rput" size 64
: q=d986f2c0, mp=d7f11860, mp->b_rptr=d7f118a0, wptr=d7f118b3
: 215469:CPU0 in lis_strrput() head/head.c #3300 -- d82ed280 0xd7f11860
: lis_strrput: loop(234,2) queueing M_DATA
: lis_head_put([EMAIL PROTECTED]/--1/1) "loop(234,1)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:4 since 0
ticks
: lis_strioctl([EMAIL PROTECTED]/1,[EMAIL PROTECTED]/2,cmd=0x5301,arg=0xbffff75c)
<< i_rdev=0xea00002
: lis_head_get([EMAIL PROTECTED]/++3/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:5 since 0
ticks
: lis_strioctl(...,I_NREAD,...) "loop(234,2)" >> bytes=19 size=1 err=0
: lis_head_put([EMAIL PROTECTED]/--2/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:6 since 0
ticks
: lis_strioctl([EMAIL PROTECTED]/1,[EMAIL PROTECTED]/2,cmd=0x531d,arg=0x3) <<
i_rdev=0xea00002
: lis_head_get([EMAIL PROTECTED]/++3/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:7 since 0
ticks
: lis_strioctl(...,I_CKBAND,3) "loop(234,2)"
: lis_head_put([EMAIL PROTECTED]/--2/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:8 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=52
: strwrite: stream printk(236,0): send 52 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116d4
: strtst: ck_band(3): I_CKBAND: got expected result 1
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:9 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:10 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++3/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: lis_strgetpmsg: q=d82ed280, mp=d7f11a60, mp->b_rptr=d7f11aa0
: strgetmsg: maxlen len return=0xffffffb6 flags=0x4 band=3
stream loop(234,2)
: control: 1000 -1 NULL-MSG
: data: 1000 -1 M_DATA
REMARK: Bad message?
: lis_head_put([EMAIL PROTECTED]/--2/1) "loop(234,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:11 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=37
: strwrite: stream printk(236,0): send 37 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116c5
REMARK:
: strtst: receive_band(3): Bad message
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
REMARK: lis_thread_runqueues again triggered (the 12. time) but not run
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:12 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:13 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=11
: strwrite: stream printk(236,0): send 11 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116ab
: strtst:
:
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:14 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:15 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=61
: strwrite: stream printk(236,0): send 61 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116dd
: strtst: ****************************************************
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:16 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:17 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=61
: strwrite: stream printk(236,0): send 61 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116dd
REMARK:
: * Test Failed *
REMARK: Not the right (no?) message did come up, probably because
lis_thread_runqueues is not processed.
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
REMARK: lis_thread_runqueues is again triggered, but does not start.
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:18 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:19 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=62
: strwrite: stream printk(236,0): send 62 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116de
: strtst: ****************************************************
:
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:20 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:21 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(intl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd7f116a0 wptr=0xd7f116a0 size=38
: strwrite: stream printk(236,0): send 38 bytes downstream to printk
: putnext: M_DATA from "str_wput" to "printk" size 64
: q=d96a98fc, mp=d7f11660, mp->b_rptr=d7f116a0, wptr=d7f116c6
: strtst: Dump of memory areas in use:
:
: lis_freeb: (mblk) bp=0xd7f11660 dp=0xd7f11684
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:22 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "printk(236,0)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:23 since 0
ticks
: lis_head_get([EMAIL PROTECTED]/++2/1) "fifo(232,3)" {head/[EMAIL PROTECTED]
: lis_malloc: 0xd8957e60: k /usr/src/LiS-2.17/head/head.c #5003,
size=160
: lis_allocb: mp=0xd7f11660 dp=0xd7f11684(extl) from mblk
/usr/src/LiS-2.17/head/head.c 5003
: rptr=0xd8957e60 wptr=0xd8957e60 size=148
: strwrite: stream fifo(232,3): send 148 bytes downstream to fifo
: putnext: M_DATA from "fifo" to "fifo" size 148
: q=d96a817c, mp=d7f11660, mp->b_rptr=d8957e60, wptr=d8957ef4
: 215953:CPU0 in lis_strrput() head/head.c #3300 -- d96a8680 0xd7f11660
: lis_strrput: fifo(232,2) queueing M_DATA
: 215972:CPU0 in lis_qenable() head/queue.c #1285 -- d2f44860 0x71
: lis_head_get([EMAIL PROTECTED]/++2/1) "fifo(232,2)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:24 since 0
ticks
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:25 since 0
ticks
: lis_head_put([EMAIL PROTECTED]/--1/1) "fifo(232,3)" {head/[EMAIL PROTECTED]
: CPU0 lis_setqsched: wake up thread on other cpu:1 triggered:26 since 0
ticks
REMARK: Now lis_thread_runqueues starts, but too late.
: CPU1 lis_thread_runqueues: got sema. lis_runq_req_cnt:2; waited 1
ticks; have been triggered 25 times in vain
: 216035:CPU1 in queuerun() head/stream.c #251 -- cb7bd860 0x71
: 216046:CPU1 in queuerun() head/stream.c #275 -- cb7bd860 0xd82ed280
: 216052:CPU1 in lis_strrsrv() head/head.c #3247 -- d82ed280 0x0
: 216070:CPU1 in lis_process_rput() head/head.c #2946 -- cb7bd860
0xd7f11e60
: 216076:CPU1 in lis_process_rput() head/head.c #2948 -- cb7bd860
0xd7f11e60
: 216085:CPU1 in lis_process_rput() head/head.c #2955 -- d82ed280
0xd7f11e60
: lis_process_rput: received M_DATA (0) from "loop" on stream
loop(234,2) size 64
: 216091:CPU1 in lis_process_rput() head/head.c #3008 -- d82ed280
0xd7f11e60
: 216097:CPU1 in lis_process_rput() head/head.c #3015 -- d7f11e60 0x0
: 216108:CPU1 in lis_process_rput() head/head.c #3208 -- d7f11e60 0x0
REMARK: The message 0xd7f11860 from above is here processed. Too late
: 216126:CPU1 in lis_process_rput() head/head.c #2946 -- cb7bd860
0xd7f11860
: 216132:CPU1 in lis_process_rput() head/head.c #2948 -- cb7bd860
0xd7f11860
: 216141:CPU1 in lis_process_rput() head/head.c #2955 -- d82ed280
0xd7f11860
: lis_process_rput: received M_DATA (0) from "loop" on stream
loop(234,2) size 64
: 216147:CPU1 in lis_process_rput() head/head.c #3008 -- d82ed280
0xd7f11860
: 216153:CPU1 in lis_process_rput() head/head.c #3015 -- d7f11860 0x0
: 216164:CPU1 in lis_process_rput() head/head.c #3208 -- d7f11860 0x0
REMARK: By the way: after that point lis_run_queues is called 25 times
in vain. I did not trace that.
.......
Dont understand this! The background process should start directly after
setting up the semaphore, because it should have a higher priority.
This is not the only case, where it takes longer time from putting the
semaphore up until the backgroundprocess starts:
Monoprocessor machine:
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 3
ticks; have been triggered 7 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 22
ticks; have been triggered 4 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 5
ticks; have been triggered 9 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 7
ticks; have been triggered 7 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:2; waited 13
ticks; have been triggered 3246 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:2; waited 6
ticks; have been triggered 978 times in vain
Dual-processor machine:
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 3
ticks; have been triggered 7 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 4
ticks; have been triggered 7 times in vain
: CPU1 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 10
ticks; have been triggered 2 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 7
ticks; have been triggered 7 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 2
ticks; have been triggered 6 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:0; waited 8
ticks; have been triggered 3 times in vain
: CPU0 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 4
ticks; have been triggered 7 times in vain
: CPU1 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 13
ticks; have been triggered 7 times in vain
: CPU1 lis_thread_runqueues: got sema. lis_runq_req_cnt:1; waited 6
ticks; have been triggered 1 times in vain
0,22 seconds and 0,13 seconds is a long time even for our slow machines.
I also measured the time how long the Streams queues are running.
Monoprocessor machine:
: CPU0 lis_thread_runqueues wait at sema. lis_runq_req_cnt:0 ; processed
lis_run_queues 14 ticks
: CPU0 lis_thread_runqueues wait at sema. lis_runq_req_cnt:0 ; processed
lis_run_queues 6 ticks
14 ticks 0,14 seconds is a very long time even for a monoprocessor
system!
On dual processor machine it is never more than 1 Tick.
But I had some traces, where one processor was working in
lis_thread_runqueues for a longer time.
I could not reproduce this problem, with appropriate traces.
**************************************************************:
Here the start up (by streams start) on the monoprocessor machine.
There is a problem creating the devices.
This problem happens also on dual-processor.
: ==================================================================
: Linux STREAMS Subsystem loading...
REMARK: Added to bring some additional information about SUSE8
: lis_init_module. Following defines set:
: NOT __SMP__
: KERNEL_2_3
....
: STREAMS driver "loop-around" registered, major 234
: mknod /dev/loop_clone: OK
REMARK: It happens often, that the mknod failes.
: mknod /dev/loop.1: error -17
REMARK: #define EEXIST 17 /* File exists
*/
REMARK: But I did check before calling streams start, and the file did
not exist.
REMARK: It sometimes needs 3 or 4 times doing: streams stop; streams
start
until the devices are installed.
: mknod /dev/loop.2: OK
...
**************** sourcecode extensions on linux-mdep.c
*************************
patch produced by: diff -Naur old new >patch_l-mdep
diff -Naur old/linux-mdep.c new/linux-mdep.c
--- old/linux-mdep.c 2004-07-28 09:44:15.000000000 +0200
+++ new/linux-mdep.c 2004-07-28 17:00:28.000000000 +0200
@@ -85,6 +85,7 @@
#include <linux/capability.h>
#endif
#include <linux/time.h>
+#include <linux/sched_runqueue.h> /* extension goh */
/* -------------------------------------------------------------------
*/
/*
@@ -3616,6 +3617,66 @@
"==================================================================\n"
"Linux STREAMS Subsystem loading...\n");
+/* goh extension */
+ printk(KERN_DEBUG " lis_init_module. Following defines set:\n");
+
+#if defined(__SMP__)
+ printk(KERN_DEBUG " __SMP__\n");
+#else
+ printk(KERN_DEBUG "NOT __SMP__\n");
+#endif
+
+#if defined(KERNEL_2_3)
+ printk(KERN_DEBUG " KERNEL_2_3\n");
+#else
+ printk(KERN_DEBUG "NOT KERNEL_2_3\n");
+#endif
+
+#if defined(KERNEL_2_5)
+ printk(KERN_DEBUG " KERNEL_2_5\n");
+#else
+ printk(KERN_DEBUG "NOT KERNEL_2_5\n");
+#endif
+
+#if defined(KERNEL_2_1)
+ printk(KERN_DEBUG " KERNEL_2_1\n");
+#else
+ printk(KERN_DEBUG "NOT KERNEL_2_1\n");
+#endif
+
+#if defined(KERNEL_2_2)
+ printk(KERN_DEBUG " KERNEL_2_2\n");
+#else
+ printk(KERN_DEBUG "NOT KERNEL_2_2\n");
+#endif
+
+#if defined(KERNEL_2_4)
+ printk(KERN_DEBUG " KERNEL_2_4\n");
+#else
+ printk(KERN_DEBUG "NOT KERNEL_2_4\n");
+#endif
+
+#if defined(LINUX)
+ printk(KERN_DEBUG " LINUX\n");
+#else
+ printk(KERN_DEBUG "NOT LINUX\n");
+#endif
+
+#if defined(__KERNEL__)
+ printk(KERN_DEBUG " __KERNEL__\n");
+#else
+ printk(KERN_DEBUG "NOT __KERNEL__\n");
+#endif
+
+ printk(KERN_DEBUG " CONFIG_MAX_USER_RT_PRIO:%d MAX_USER_RT_PRIO:%d
MAX_RT_PRIO:%d MAX_PRIO:%d \n",
+ CONFIG_MAX_USER_RT_PRIO,
+ MAX_USER_RT_PRIO,
+ MAX_RT_PRIO,
+ MAX_PRIO);
+/* goh extension */
+
+
+
current->fs->umask = 0 ; /* can set any permissions */
lis_mem_init() ; /* in lismem.c */
@@ -3939,6 +4000,12 @@
return(kill_proc(pid, SIGTERM, 1));
}
+ /*goh*/
+lis_atomic_t triggered[10]={0};
+/* extern unsigned long volatile jiffies; */
+unsigned long trig_time[10]={0};
+unsigned long start_time[10]={0};
+ /*goh*/
/***********************************************************************
*
* Queue Running
*
@@ -3973,6 +4040,10 @@
lis_semaphore_t *semp = &lis_runq_sems[cpu_id] ;
extern char lis_print_buffer[] ;
extern char *lis_nxt_print_ptr ;
+ /*goh*/
+ int print_flag=0;
+ int my_cpu;
+ /*goh*/
printk(KERN_INFO "LiS-RunQ-%s running on CPU %d pid=%d\n",
lis_version, cpu_id, current->pid) ;
@@ -3994,6 +4065,15 @@
#else
schedule() ; /* maybe this will do the same
*/
#endif
+
+ /*goh*/
+ my_cpu = smp_processor_id() ;
+ printk(KERN_INFO "lis_thread_runqueues After schedule. LiS-RunQ
with pid:%d running on cpu: %d should be on cpu:%d\n",
+ current->pid, my_cpu, cpu_id) ; /* extension goh*/
+
+ K_ATOMIC_INC(&triggered[cpu_id]); /* here is an automatic trigger
*/
+ /*goh*/
+
for (;;)
{
lis_run_queues(cpu_id) ; /* run the STREAMS queues */
@@ -4005,6 +4085,19 @@
* will go away from a KILL or INT signal so that we can also
* be easily killed from the keyboard.
*/
+
+ /*goh*/
+ if((current->policy != SCHED_FIFO)||(current->rt_priority !=
50)) /* goh for test */
+ printk(KERN_DEBUG "lis_thread_runqueues: different
policy:%ld rt_priority:%ld \n",current->policy, current->rt_priority );
/* goh for test */
+
+
+ if(print_flag==1)
+ {
+ printk(KERN_DEBUG "CPU%d lis_thread_runqueues wait at sema.
lis_runq_req_cnt:%d ; processed lis_run_queues %ld
ticks\n",my_cpu,lis_atomic_read(&lis_runq_req_cnt),jiffies-start_time[cp
u_id]); /* goh for test */
+ print_flag=0;
+ }
+ /*goh*/
+
if (lis_down(semp) < 0) /* sleep */
{ /* interrupted */
if ( signal_pending(current) /* killed */
@@ -4023,6 +4116,19 @@
else
sig_cnt = 0 ;
+ /*goh*/
+ K_ATOMIC_DEC(&triggered[cpu_id]);
+
+ if(trig_time[cpu_id]!=0)
+ {
+ printk(KERN_DEBUG "CPU%d lis_thread_runqueues: got sema.
lis_runq_req_cnt:%d; waited %ld ticks; have been triggered %d times in
vain\n",my_cpu,lis_atomic_read(&lis_runq_req_cnt), jiffies -
trig_time[cpu_id],K_ATOMIC_READ(&triggered[cpu_id])); /* goh for test
*/
+ trig_time[cpu_id]=0;
+ start_time[cpu_id]=jiffies;
+ print_flag=1;
+ }
+ /*goh*/
+
+
lis_runq_wakeups[cpu_id]++ ;
if (cpu_id != smp_processor_id())
{
@@ -4112,6 +4218,137 @@
}
}
+/* #define DIRECT_CALL */
+
+#ifdef DIRECT_CALL
+/*
+ * The "can_call" parameter is true if it is OK to just call the queue
runner
+ * from this routine. It is false if it is necessary to defer the
queue
+ * running until later. Typically qenable() passes 0 and others pass
1.
+ */
+void lis_setqsched(int can_call) /* kernel thread style
*/
+{
+ int queues_running ;
+ int queue_load_thresh ;
+ int req_cnt ;
+ int in_intr = in_interrupt() ;
+ int my_cpu = smp_processor_id() ;
+ static int qsched_running ;
+ lis_flags_t psw;
+
+#define WORK_INCR 13
+
+ lis_spin_lock_irqsave(&lis_setqsched_lock, &psw) ;
+
+ /*
+ printk(KERN_DEBUG "lis_setqsched enter: installed threads: %d
actual running: %d requests: %d on cpu: %d\n",
+ lis_atomic_read(&lis_runq_cnt),
+ lis_atomic_read(&lis_queues_running),
+ lis_atomic_read(&lis_runq_req_cnt),
+ my_cpu);
+ */
+
+ lis_setqsched_cnts[my_cpu]++ ; /* keep statistics */
+ if (in_intr)
+ lis_setqsched_isr_cnts[my_cpu]++ ; /* keep statistics */
+
+ if (qsched_running)
+ { /* one of these is
enough */
+ printk(KERN_DEBUG "CPU%d lis_setqsched error exit runs several
times; qsched_running:%d\n",my_cpu, qsched_running); /* goh for test */
+ lis_spin_unlock_irqrestore(&lis_setqsched_lock, &psw) ;
+ return ;
+ }
+
+ qsched_running = 1 ;
+ lis_spin_unlock_irqrestore(&lis_setqsched_lock, &psw) ;
+
+ if (K_ATOMIC_READ(&lis_runq_cnt) == 0)
+ { /* no threads running */
+ static int cnt ;
+
+ if (cnt++ < 5)
+ printk("CPU%d lis_setqsched: error exit No qrun
process\n",my_cpu);
+
+ goto return_point ;
+ }
+
+
+ queues_running = K_ATOMIC_READ(&lis_queues_running) ;
+ queue_load_thresh = WORK_INCR * queues_running ;
+ req_cnt = K_ATOMIC_READ(&lis_runq_req_cnt) ;
+
+ /*
+ * If the number of outstanding requests does not cross the upper
+ * threhold for needing more queue run threads running, or if they
+ * are all running already, just return. There is nothing that we
+ * can do to improve things.
+ */
+ if ( req_cnt <= queue_load_thresh
+ || queues_running == K_ATOMIC_READ(&lis_runq_cnt)
+ )
+ {
+ int trig,i;
+ trig=0;
+ for(i=0;i<K_ATOMIC_READ(&lis_runq_cnt);i++)
+ trig=trig+K_ATOMIC_READ(&triggered[i]);
+
+ printk(KERN_DEBUG "CPU%d lis_setqsched exit enough:
queues_running: %d req_cnt:%d triggered all:%d
\n",my_cpu,queues_running,req_cnt,trig ); /* goh for test */
+ goto return_point ;
+ }
+
+ if (!K_ATOMIC_READ(&lis_runq_active_flags[my_cpu]))
+ {
+ if ((lis_atomic_read(&lis_in_syscall) == 0) && (in_intr==0) &&
(can_call!=0))/* not in a system call */
+ {
+
+ if(trig_time[my_cpu]==0)
+ {
+ trig_time[my_cpu]=jiffies;
+ }
+
+ printk(KERN_DEBUG "CPU%d lis_setqsched: direct call of
lis_run_queues on own cpu triggered:%d since %ld ticks\n",
+ my_cpu,
+ K_ATOMIC_READ(&triggered[my_cpu]),
+ jiffies-trig_time[my_cpu]); /* goh for
test */
+
+ trig_time[my_cpu]=0;
+ start_time[my_cpu]=jiffies;
+
+ lis_run_queues(my_cpu);
+
+ printk(KERN_DEBUG "CPU%d lis_setqsched: finished
lis_runqueues. lis_runq_req_cnt:%d ; processed lis_run_queues %ld
ticks\n",my_cpu,lis_atomic_read(&lis_runq_req_cnt),jiffies-start_time[my
_cpu]); /* goh for test */
+
+
+ }
+ else
+ { /* could trigger also on other cpu; for later
implementation */
+
+ K_ATOMIC_INC(&triggered[my_cpu]);
+
+ if(trig_time[my_cpu]==0)
+ {
+ trig_time[my_cpu]=jiffies;
+ }
+
+ printk(KERN_DEBUG "CPU%d lis_setqsched: wake up thread on
own cpu lis_in_syscall:%d in_int:%d can_call:%d triggered:%d since %ld
ticks\n",
+ my_cpu,
+ lis_atomic_read(&lis_in_syscall),
+ in_intr,
+ can_call,
+ K_ATOMIC_READ(&triggered[my_cpu]),
+ jiffies-trig_time[my_cpu]); /* goh for
test */
+
+ lis_up(&lis_runq_sems[my_cpu]) ; /* wake up thread
on my cpu */
+ }
+ }
+return_point:
+ qsched_running = 0 ;
+
+} /* lis_setqsched */
+
+#else
+
+
/*
* The "can_call" parameter is true if it is OK to just call the queue
runner
* from this routine. It is false if it is necessary to defer the
queue
@@ -4132,12 +4369,25 @@
lis_spin_lock_irqsave(&lis_setqsched_lock, &psw) ;
+ /* goh for test */
+ /*
+ printk(KERN_DEBUG "lis_setqsched enter: installed threads: %d
actual running: %d requests: %d on cpu: %d\n",
+ lis_atomic_read(&lis_runq_cnt),
+ lis_atomic_read(&lis_queues_running),
+ lis_atomic_read(&lis_runq_req_cnt),
+ my_cpu);
+ */
+ /* goh for test */
+
lis_setqsched_cnts[my_cpu]++ ; /* keep statistics */
if (in_intr)
lis_setqsched_isr_cnts[my_cpu]++ ; /* keep statistics */
if (qsched_running)
{ /* one of these is
enough */
+ /*goh*/
+ printk(KERN_DEBUG "CPU%d lis_setqsched error exit runs several
times; qsched_running:%d\n",my_cpu, qsched_running); /* goh for test */
+ /*goh*/
lis_spin_unlock_irqrestore(&lis_setqsched_lock, &psw) ;
return ;
}
@@ -4150,7 +4400,9 @@
static int cnt ;
if (cnt++ < 5)
- printk("lis_setqsched: No qrun process\n");
+ /*goh*/
+ printk("CPU%d lis_setqsched: error exit No qrun
process\n",my_cpu);
+ /*goh*/
goto return_point ;
}
@@ -4210,8 +4462,17 @@
if ( req_cnt <= queue_load_thresh
|| queues_running == K_ATOMIC_READ(&lis_runq_cnt)
)
- goto return_point ;
+ {
+ /*goh*/
+ int trig,i;
+ trig=0;
+ for(i=0;i<K_ATOMIC_READ(&lis_runq_cnt);i++)
+ trig=trig+K_ATOMIC_READ(&triggered[i]);
+ printk(KERN_DEBUG "CPU%d lis_setqsched exit enough:
queues_running: %d req_cnt:%d triggered all:%d
\n",my_cpu,queues_running,req_cnt,trig ); /* goh for test */
+ /*goh*/
+ goto return_point ;
+ }
/*
* We could benefit by having another queue run thread wake up
* and help with the queue processing. Don't wake up my cpu
@@ -4223,10 +4484,22 @@
if ( cpu != my_cpu /* don't start on my cpu yet */
&& !K_ATOMIC_READ(&lis_runq_active_flags[cpu]))
{ /* sleeping thread */
+ /*goh*/
+ K_ATOMIC_INC(&triggered[cpu]);
+
+ if(trig_time[cpu]==0)
+ {
+ trig_time[cpu]=jiffies;
+ }
+ printk(KERN_DEBUG "CPU%d lis_setqsched: wake up thread on
other cpu:%d triggered:%d since %ld
ticks\n",my_cpu,cpu,K_ATOMIC_READ(&triggered[cpu]),
jiffies-trig_time[cpu]); /* goh for test */
+ /*goh*/
+
lis_up(&lis_runq_sems[cpu]) ; /* wake up a thread */
queue_load_thresh += WORK_INCR ; /* increase threshold */
if (K_ATOMIC_READ(&lis_runq_req_cnt) <= queue_load_thresh)
+ {
goto return_point ; /* enough threads
running */
+ }
}
}
@@ -4235,12 +4508,32 @@
* my_cpu is available.
*/
if (!K_ATOMIC_READ(&lis_runq_active_flags[my_cpu]))
- lis_up(&lis_runq_sems[my_cpu]) ; /* wake up thread on my
cpu */
+ {
+ /*goh*/
+ K_ATOMIC_INC(&triggered[my_cpu]);
+
+ if(trig_time[my_cpu]==0)
+ {
+ trig_time[my_cpu]=jiffies;
+ }
+
+ printk(KERN_DEBUG "CPU%d lis_setqsched: wake up thread on own
cpu lis_in_syscall:%d in_int:%d can_call:%d triggered:%d since %ld
ticks\n",
+ my_cpu,
+ lis_atomic_read(&lis_in_syscall),
+ in_intr,
+ can_call,
+ K_ATOMIC_READ(&triggered[my_cpu]),
+ jiffies-trig_time[my_cpu]); /* goh for test
*/
+ /*goh*/
+
+ lis_up(&lis_runq_sems[my_cpu]) ; /* wake up thread on my
cpu */
+ }
return_point:
qsched_running = 0 ;
} /* lis_setqsched */
+#endif
/*
* Called from head code when time to unload LiS module.
_______________________________________________
Linux-streams mailing list
[EMAIL PROTECTED]
http://gsyc.escet.urjc.es/mailman/listinfo/linux-streams
