陶捷 TaoJie
2008-Jan-17 16:20 UTC
[dtrace-discuss] Under DTrace USDT and PID, kernel''s microstat accounting doesn''t work in this situation, doesn''t it?
Does anyone has any ideas about this problem? 2008/1/15, ?? TaoJie <eulertao at gmail.com>:> > Hi all: > > I''m working on revealing system performance now. > My testing program is an infinite loop. Inside the loop, it will do some > mathematical opertaions and call function callee(), then go to the next > loop. > I install a alarm(30) in the program. It means it will stop after running > 30 seconds. > Before calling alarm(30), at the beginning of the main body, it will use > libkstat to read kstat-cpu-sys record first. > After the alarm signal raised, in the signal handler, it will re-read the > kstat-cpu-sys record, and show the difference in this 30 seconds period. > > For example, following is output printed on the screen, > *30.00 secs, 0.00 events per secs > user=99.7279%, kernel=0.2721%, idle=0.0000% > per second: intr=308.64, ithr=208.63, syscall=1.80, csw=78.14 > per second: smtx=0.33, srw=0.00 > per second: migr=0.00 > * //Events are some syscalls or some user-defined functions. > > In a word, this program looks very like the mpstat. > > One of my testcases is running this program with dtrace''s fasttrap > provider, such as: > dtrace -n ''pid$targer::callee:entry{ ... }'' -c my_program > dtrace -n ''test$target:::callee{ ... }'' -c my_program > > The output is very strange. > *30.00 secs, 213099.33 per secs > user=99.6749%, kernel=0.3251%, idle=0.0000% > per second: intr=513.15, ithr=312.13, syscall=48.67, csw=87.27 > per second: smtx=0.10, srw=0.00 > per second: migr= 0.00* > > In the infinite loop, callee would be called more than 2000000 times. Each > time it is called, the program would trap into kernel because it is > monitored by dtrace. > > Compared with the program running with no dtrace, > *30.00 secs, 100628.74 per secs > user=99.7396%, kernel=0.2604%, idle=0.0000% > per second: intr=308.89, ithr=208.89, syscall=3.13, csw=73.24 > per second: smtx=0.17, srw=0.00 > per second: migr= 0.00 > * > No big difference between these 2 kernel time percentages! > > I think this is unbelievable! And maybe the answer is microstat accounting > system cannot log this kind of interrupt. > Since I try this program on Intel P4 platform. In i86pc, dtrace using "int > $3" to help the user program to trap into dtrace kernel module. > > So, does it means that the mircostat accouting does not work in "int $3" > and some other cases? > Am I right? > > P.S. I''m using ON build 74. > Thank you. > > > Kind Regards, > TJ >-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20080118/27d1c736/attachment.html>
Dan Mick
2008-Jan-17 18:14 UTC
[dtrace-discuss] [osol-code] Under DTrace USDT and PID, kernel''s microstat accounting doesn''t work in this situation, doesn''t it?
MY *guess* would be that int 3 (if indeed that''s the PID provider''s mechanism; I haven''t checked) isn''t accounted as "system" or "interrupt" time by choice...because the process really isn''t voluntarily in the system for any ''real'' reason. I don''t know; reading the code would illuminate, of course, but I''m really not surprised. Why are you surprised, or why do you care? ?? TaoJie wrote:> Does anyone has any ideas about this problem? > > 2008/1/15, ?? TaoJie <eulertao at gmail.com <mailto:eulertao at gmail.com>>: > > Hi all: > > I''m working on revealing system performance now. > My testing program is an infinite loop. Inside the loop, it will do > some mathematical opertaions and call function callee(), then go to > the next loop. > I install a alarm(30) in the program. It means it will stop after > running 30 seconds. > Before calling alarm(30), at the beginning of the main body, it will > use libkstat to read kstat-cpu-sys record first. > After the alarm signal raised, in the signal handler, it will > re-read the kstat-cpu-sys record, and show the difference in this 30 > seconds period. > > For example, following is output printed on the screen, > /30.00 secs, 0.00 events per secs > user=99.7279%, kernel=0.2721%, idle=0.0000% > per second: intr=308.64, ithr=208.63, syscall=1.80, csw=78.14 > per second: smtx=0.33, srw=0.00 > per second: migr=0.00 > / //Events are some syscalls or some user-defined functions. > > In a word, this program looks very like the mpstat. > > One of my testcases is running this program with dtrace''s fasttrap > provider, such as: > dtrace -n ''pid$targer::callee:entry{ ... }'' -c my_program > dtrace -n ''test$target:::callee{ ... }'' -c my_program > > The output is very strange. > /30.00 secs, 213099.33 per secs > user=99.6749%, *kernel=0.3251%*, idle=0.0000% > per second: intr=513.15, ithr=312.13, syscall=48.67, csw=87.27 > per second: smtx=0.10, srw=0.00 > per second: migr= 0.00/ > > In the infinite loop, callee would be called more than 2000000 > times. Each time it is called, the program would trap into kernel > because it is monitored by dtrace. > > Compared with the program running with no dtrace, > /30.00 secs, 100628.74 per secs > user=99.7396%, *kernel=0.2604%*, idle=0.0000% > per second: intr=308.89, ithr=208.89, syscall=3.13, csw=73.24 > per second: smtx=0.17, srw=0.00 > per second: migr= 0.00 > / > No big difference between these 2 kernel time percentages! > > I think this is unbelievable! And maybe the answer is microstat > accounting system cannot log this kind of interrupt. > Since I try this program on Intel P4 platform. In i86pc, dtrace > using "int $3" to help the user program to trap into dtrace kernel > module. > > So, does it means that the mircostat accouting does not work in "int > $3" and some other cases? > Am I right? > > P.S. I''m using ON build 74. > Thank you. > > > Kind Regards, > TJ > > > > ------------------------------------------------------------------------ > > _______________________________________________ > opensolaris-code mailing list > opensolaris-code at opensolaris.org > http://mail.opensolaris.org/mailman/listinfo/opensolaris-code