Michael was sitting in my living room this evening and we were discussion performance issues and I was musing about adding an instrumentation printf to the Squeak VM to grab the method name on each execution of a message send. That way we *know* what messages are being sent in which order. So I decided to code up a test macintosh carbon VM that is found at hftp://ftp.smalltalkconsulting.com/ experimental/SqueakMethodTrace3.8.9b7.app.zip which dumps data to 'messageTraceFile.txt'
One of the things I saw a lot of when opening an image, which generates 40MB of data, is this sequence.
Process context Increment GC count method 107493580 111893480 16 StrikeFontSet>glyphInfoOf:into: 107493580 111893572 16 StrikeFont>ascentOf: 107493580 111893940 16 StrikeFont>hasGlyphOf: 107493580 111894032 16 Character>charCode 107493580 111893940 16 StrikeFont>hasGlyphOf: 107493580 111893940 16 StrikeFont>hasGlyphOf: 107493580 111894032 16 Magnitude>between:and: 107493580 111893940 16 StrikeFont>hasGlyphOf: 107493580 111893572 16 StrikeFont>ascentOf: 107493580 111893480 16 SequenceableCollection>first 107493580 111893480 16 SequenceableCollection>first 107493580 111893480 16 SequenceableCollection>second 107493580 111893572 16 SequenceableCollection>checkedAt: 107493580 111893572 16 SequenceableCollection>checkedAt: 107493580 111893480 16 SequenceableCollection>third 107493580 111893572 16 SequenceableCollection>checkedAt: 107493580 111893572 16 SequenceableCollection>checkedAt: 107493580 111893480 16 SequenceableCollection>fifth 107493580 111893572 16 SequenceableCollection>checkedAt: 107493580 111893572 16 SequenceableCollection>checkedAt:
what is interesting is that StrikeFontSet>displayString:on:from:to:at:kern:baselineY:
does
self glyphInfoOf: (aString at: charIndex) into: glyphInfo. g := glyphInfo first. leftX := glyphInfo second. rightX := glyphInfo third. (glyphInfo fifth ~= aBitBlt lastFont) ifTrue: [ glyphInfo fifth installOn: aBitBlt. ].
Now for example SquenceableCollection>>fifth "Answer the fifth element of the receiver. Raise an error if there are not enough elements."
^ self checkedAt: 5
which does
SquenceableCollection>>checkedAt: index index > self size ifTrue: [self error: 'not enough elements']. ^ self at: index
which does the at: index which would in fact toss an self errorSubscriptBounds: when the primitive discovers a range check issue.
So do we need the checkedAt: logic? Could we just not say fifth ^self at: 5
Of course saying (self at: 5) in displayString:on:from:to:at:kern:baselineY: would be way more efficient.
Other fun things like Rectangle>insetBy: invokes isKindOf: versus saying isThisARectangle or something...
String>convertFromWithConverter: is quite message sending happy.
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
John
Marcus introduced a simple fix in 6695 to use isRectangle.
I have the impression that may be the real fix would be to have two methods but I did not check the senders....
Other fun things like Rectangle>insetBy: invokes isKindOf: versus saying isThisARectangle or something...
John M McIntosh puso en su mail :
Michael was sitting in my living room this evening and we were discussion performance issues and I was musing about adding an instrumentation printf to the Squeak VM to grab the method name on each execution of a message send. That way we *know* what messages are being sent in which order. So I decided to code up a test macintosh carbon VM that is found at hftp://ftp.smalltalkconsulting.com/ experimental/SqueakMethodTrace3.8.9b7.app.zip which dumps data to 'messageTraceFile.txt'
John: I very interested in grab grab the method name on each execution of a message send. I download your SqueakMethodTrace3.8.9b7.app and start 3.8 , but don't found messageTraceFile.txt. What could I doing wrong ? Exist some form of I could choose what wish profile ?
Very thanks in advance.
edgar
___________________________________________________________ 1GB gratis, Antivirus y Antispam Correo Yahoo!, el mejor correo web del mundo http://correo.yahoo.com.ar
John: Forget my previous mail. I found the .txt. Very, very thanks for this work. Still wish know if I could start/stop the profiling for I choose what profile.
Edgar
___________________________________________________________ 1GB gratis, Antivirus y Antispam Correo Yahoo!, el mejor correo web del mundo http://correo.yahoo.com.ar
Let me add a primitive to turn that on or off
On 29-Oct-05, at 5:22 AM, Lic. Edgar J. De Cleene wrote:
John: Forget my previous mail. I found the .txt. Very, very thanks for this work. Still wish know if I could start/stop the profiling for I choose what profile.
Edgar
1GB gratis, Antivirus y Antispam Correo Yahoo!, el mejor correo web del mundo http://correo.yahoo.com.ar
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
On 29-Oct-05, at 8:50 AM, John M McIntosh wrote:
Let me add a primitive to turn that on or off
There are already primitives for controlling profiling. Just use those! clearProfile, dumpProfile, startProfiling, stopProfiling
tim
In the very near future, I plan to work on profiling technics. The question I want to ask you is: What are the information we want to obtain from a program execution?
Here are some thoughts: - 2 kinds of profiling: time and speed. How long methods of my application takes ? How much memory my application requires ? - minimize the amount of information by restricting the output of the profiler to the information I am really interested in. Basically, If I define a seaside application, I am only concerned by my application, and not by the seaside framework. - Currently, in Squeak, I can only listen to everything (i.e., every method call is measured). It might be interesting to limit the measurement to a small part of the system (e.g., objets).
I would be really interested in hearing your opinion...
Regards, Alexandre
On Oct 29, 2005, at 6:36 PM, tim Rowledge wrote:
On 29-Oct-05, at 8:50 AM, John M McIntosh wrote:
Let me add a primitive to turn that on or off
There are already primitives for controlling profiling. Just use those! clearProfile, dumpProfile, startProfiling, stopProfiling
tim
tim Rowledge; tim@rowledge.org; http://www.rowledge.org/tim
If you're attempting a serious attack on profiling you ought to include some time looking at how to make profiling work in the face of long running primitives. The profiles we get when using TimeProfiler et al can be quite innaccurate if the code being profiled uses prims that take a long time; the process that interrupts to sample the subject code cannot actually interrupt inside such a long prim.
I forget how it was tackled but VW has some code to try to improve the value of the results, or used to. It is possible that later changes have obviated the problem or changed it beyond obvious similarity.
tim
Sure.
However, dealing with primitive (or native code) has always been a challenge to profile... thanks Tim for your comment.
Cheers, Alexandre
On Oct 29, 2005, at 7:50 PM, tim Rowledge wrote:
If you're attempting a serious attack on profiling you ought to include some time looking at how to make profiling work in the face of long running primitives. The profiles we get when using TimeProfiler et al can be quite innaccurate if the code being profiled uses prims that take a long time; the process that interrupts to sample the subject code cannot actually interrupt inside such a long prim.
I forget how it was tackled but VW has some code to try to improve the value of the results, or used to. It is possible that later changes have obviated the problem or changed it beyond obvious similarity.
tim
tim Rowledge; tim@rowledge.org; http://www.rowledge.org/tim
Hello Alexandre,
happy to hear you will work on this! AB> Here are some thoughts: AB> - 2 kinds of profiling: time and speed. How long methods of my AB> application takes ? How much memory my application requires ?
one thing I always miss: the time spent in my code vs. the total time spent in the method. I always have to write something to find out never knowing if my simplifications are valid.
Example: my code is iterating over an ordered collection and I want to know if OrderedCollection>>do: already takes a significant time of it all, so it's not worth speeding up my method.
Also I'd like a non indented display in the ProfileBrowser, just methods ordered by the time spent inside them and the number of sends.
ClassName>>messageName, timeSpentHere, numberOfSends, ordered by time.
The number of sends is important, it is a difference to reduce the number of sends or to speed up the code.
AB> - Currently, in Squeak, I can only listen to everything (i.e., AB> every method call is measured). It might be interesting to limit the AB> measurement to a small part of the system (e.g., objets).
A good idea! Please extend it to isKindOf as a way to select objects included into the measurement.
There is another area which I call "activity spikes" lacking a better description. Think of responsiveness of an UI. Think of real time processing, like not missing an audio sample.
I'd like to have a trigger when the time spent in a block of code exceeds a certain time. Then I'd like to get a trace of sends to find out what lead to this situation.
This needs a finer grained timer, as it's not an option to divide the obtained time by the number of executions.
Also a trigger on number of sends. The objects you mention also belong to the triggers.
A trace and triggers are important in profiling.
And please keep me (or the list) posted in this matter!
Cheers,
Herbert mailto:herbertkoenig@gmx.net
I should say that I have often problems to understand the results of the profiling tools. On VW I started to get it by comparing several execution of different ways to implement the same.
May be this is just a UI problem so that I understand how to deeply understand what I see. But I'm ready to be a guinea pig to any tools helping me to optimize my code or just understanding how to access it.
Knowing also place in the code that generates a lot of object: ie collect for example, it would be nice to annotate the method code and to get data of the previous runs.
I was also thinking that it would be nice to have a mode in the browser that shows which parts of the code is run, or has been run: following the idea of the coverage browser in VW. Because may be part of the code is never executed.
Stef
Hi Alex,
perhaps comprehensive system accounting (CSA) is a starter to see what ideas are already around for everyday's system accounting (for such long runners as Seaside). - http://www.google.com/search?q=comprehensive+system+accounting+csa
In any case I think that accounting for memory and cpu should be per process (and so I would see my favorite memory integral again :) but that would require changes to ObjectMemory (object instantiation + GC) ...
Into quite another direction goes the polymorphism metrics, which addresses the actual receiver and/or target method per call site, and can serve as a measurement of an application's object-orientedness, etc. This should also be per process (or, better perhaps per ClassBox). - http://www.google.com/search?q=call+site+polymorphic
Hope that's not too much ;)
/Klaus
On Sat, 29 Oct 2005 19:04:34 +0200, Alexandre Bergel bergel@iam.unibe.ch wrote:
In the very near future, I plan to work on profiling technics. The question I want to ask you is: What are the information we want to obtain from a program execution?
Here are some thoughts: - 2 kinds of profiling: time and speed. How long methods of my application takes ? How much memory my application requires ? - minimize the amount of information by restricting the output of the profiler to the information I am really interested in. Basically, If I define a seaside application, I am only concerned by my application, and not by the seaside framework. - Currently, in Squeak, I can only listen to everything (i.e., every method call is measured). It might be interesting to limit the measurement to a small part of the system (e.g., objets).
I would be really interested in hearing your opinion...
Regards, Alexandre
On Oct 29, 2005, at 6:36 PM, tim Rowledge wrote:
On 29-Oct-05, at 8:50 AM, John M McIntosh wrote:
Let me add a primitive to turn that on or off
There are already primitives for controlling profiling. Just use those! clearProfile, dumpProfile, startProfiling, stopProfiling
tim --tim Rowledge; tim@rowledge.org; http://www.rowledge.org/tim
Well Process>>resume: in the vm is where process switch. A few years back I wrote a change set and altered Process to track millisecond clock time, start dispatch, end of dispatch, and total time dispatched. That let you understand the clock time that a process had to run with (not the same as cpu time). One could also track the allocation count for a process by tracking that by the active processor structure when new is invoked.
On 29-Oct-05, at 1:00 PM, Klaus D. Witzel wrote:
Hi Alex,
perhaps comprehensive system accounting (CSA) is a starter to see what ideas are already around for everyday's system accounting (for such long runners as Seaside).
In any case I think that accounting for memory and cpu should be per process (and so I would see my favorite memory integral again :) but that would require changes to ObjectMemory (object instantiation + GC) ...
Into quite another direction goes the polymorphism metrics, which addresses the actual receiver and/or target method per call site, and can serve as a measurement of an application's object- orientedness, etc. This should also be per process (or, better perhaps per ClassBox).
Hope that's not too much ;)
/Klaus
On Sat, 29 Oct 2005 19:04:34 +0200, Alexandre Bergel bergel@iam.unibe.ch wrote:
In the very near future, I plan to work on profiling technics. The question I want to ask you is: What are the information we want to obtain from a program execution?
Here are some thoughts: - 2 kinds of profiling: time and speed. How long methods of my application takes ? How much memory my application requires ? - minimize the amount of information by restricting the output of the profiler to the information I am really interested in. Basically, If I define a seaside application, I am only concerned by my application, and not by the seaside framework. - Currently, in Squeak, I can only listen to everything (i.e., every method call is measured). It might be interesting to limit the measurement to a small part of the system (e.g., objets).
I would be really interested in hearing your opinion...
Regards, Alexandre
On Oct 29, 2005, at 6:36 PM, tim Rowledge wrote:
On 29-Oct-05, at 8:50 AM, John M McIntosh wrote:
Let me add a primitive to turn that on or off
There are already primitives for controlling profiling. Just use those! clearProfile, dumpProfile, startProfiling, stopProfiling
tim --tim Rowledge; tim@rowledge.org; http://www.rowledge.org/tim
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
Herbert, Stéf, Klaus, John,
thanks very much for your feedback. I am really excited by this idea of profiling. you count on me to ask you to be testers :-)
Cheers, Alexandre
On Oct 29, 2005, at 11:36 PM, John M McIntosh wrote:
Well Process>>resume: in the vm is where process switch. A few years back I wrote a change set and altered Process to track millisecond clock time, start dispatch, end of dispatch, and total time dispatched. That let you understand the clock time that a process had to run with (not the same as cpu time). One could also track the allocation count for a process by tracking that by the active processor structure when new is invoked.
On 29-Oct-05, at 1:00 PM, Klaus D. Witzel wrote:
Hi Alex,
perhaps comprehensive system accounting (CSA) is a starter to see what ideas are already around for everyday's system accounting (for such long runners as Seaside).
In any case I think that accounting for memory and cpu should be per process (and so I would see my favorite memory integral again :) but that would require changes to ObjectMemory (object instantiation + GC) ...
Into quite another direction goes the polymorphism metrics, which addresses the actual receiver and/or target method per call site, and can serve as a measurement of an application's object- orientedness, etc. This should also be per process (or, better perhaps per ClassBox).
Hope that's not too much ;)
/Klaus
On Sat, 29 Oct 2005 19:04:34 +0200, Alexandre Bergel bergel@iam.unibe.ch wrote:
In the very near future, I plan to work on profiling technics. The question I want to ask you is: What are the information we want to obtain from a program execution?
Here are some thoughts: - 2 kinds of profiling: time and speed. How long methods of my application takes ? How much memory my application requires ? - minimize the amount of information by restricting the output of the profiler to the information I am really interested in. Basically, If I define a seaside application, I am only concerned by my application, and not by the seaside framework. - Currently, in Squeak, I can only listen to everything (i.e., every method call is measured). It might be interesting to limit the measurement to a small part of the system (e.g., objets).
I would be really interested in hearing your opinion...
Regards, Alexandre
On Oct 29, 2005, at 6:36 PM, tim Rowledge wrote:
On 29-Oct-05, at 8:50 AM, John M McIntosh wrote:
Let me add a primitive to turn that on or off
There are already primitives for controlling profiling. Just use those! clearProfile, dumpProfile, startProfiling, stopProfiling
tim --tim Rowledge; tim@rowledge.org; http://www.rowledge.org/tim
--
===== John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http:// www.smalltalkconsulting.com ====================================================================== =====
To profile the VM, I banged on it until I was able to compile it non-inlined and then I tried to run a profiler on it. Unfortunately, it was far too slow to use. =\ -- the configuration might be useful for coverage testing though...
tim Rowledge puso en su mail :
There are already primitives for controlling profiling. Just use those! clearProfile, dumpProfile, startProfiling, stopProfiling
Tim: Very thanks to you too.
Edgar
___________________________________________________________ 1GB gratis, Antivirus y Antispam Correo Yahoo!, el mejor correo web del mundo http://correo.yahoo.com.ar
Actually, I half take back that suggestion to use clear/dump/start/ stop profiling; those are relic stub prims in the primitive table and ought to be excised sometime soon. Using the similar names as named prims in the null-module (ie they can be included in the vm like the powermanagement prim) should be fine. That would make them optional and they can be left out to save space when people want to make minimalist VMs.
tim
Hi tim
I was exactly wondering is they were used.
Actually, I half take back that suggestion to use clear/dump/start/ stop profiling; those are relic stub prims in the primitive table and ought to be excised sometime soon.
Should we deprecated them?
Using the similar names as named prims in the null-module (ie they can be included in the vm like the powermanagement prim) should be fine. That would make them optional and they can be left out to save space when people want to make minimalist VMs.
tim
tim Rowledge; tim@rowledge.org; http://www.rowledge.org/tim
Ok, first I missed the note that how Apple made the os 8.x call to set the working directory that worked under os-x obsolete in 10.4.x. So as you noticed it would create the .txt file in the root volume.
However now I have recompiled a change to set the application directory to the working directory. This might also fix the issues of where does the Squeak3D.log file go too.
In doing all this, a long afternoon I might add, I altered the logic so that.
a) You can with the attached change set JMMRecordMsgSendInterface. 1.cs invoke:
Smalltalk setVMStatsTraceMessageSendLevels: 1.
to set message send recording on. Note that you pass an integer so you can say
Smalltalk setVMStatsTraceMessageSendLevels: 5.
to set the number of levels in the call stack to print to 5.
Smalltalk setVMStatsTraceMessageSendLevels: 0.
turns the recording off, and closes the file, the file is always opened truncated writing.
b) As an extra feature based on conversation with Michael at breakfast this morning you can also do under os-x (unix/darwin) a kill signal to turn recording on.
kill -USR1 19278 {Pick a squeak VM process id}
kill -USR1 19278 {increment the level by one, go to 2} kill -USR1 19278 {increment the level by one, go to 3}
kill -USR2 19278 {turn recording off, and close the file}
I'll also publish the changeset JMMRecordMsgSends.1.cs (attached) which has the changes to Interpreter to enable recording, so that people with linux or darwin can build a unix VM. Keep in mind you will need to fiddle with the class changes to Interpreter if you choose to build an older unix VM at the pre beta VMMaker-tpr-37.mcz level, and the update to declareCVarsIn:, and initializeInterpreter:.
The two instance variables I added are: "vmStatsTraceMessageSendLevels vmStatsTraceMessageSendStorageFile"
c) I've posted a SqueakMethodTrace_2_3.8.9b7.app.zip file to ftp:// ftp.smalltalkconsulting.com for the mac users to field test.
On 29-Oct-05, at 5:22 AM, Lic. Edgar J. De Cleene wrote:
John: Forget my previous mail. I found the .txt. Very, very thanks for this work. Still wish know if I could start/stop the profiling for I choose what profile.
Edgar
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
John:
Thanks a lot again. As I write in my acknowledges , you not only are a master, you are "indispensable squeaker".
Gracias desde Rosario, Argentina.
Edgar
___________________________________________________________ 1GB gratis, Antivirus y Antispam Correo Yahoo!, el mejor correo web del mundo http://correo.yahoo.com.ar
On Sat, Oct 29, 2005 at 09:46:39PM -0700, John M McIntosh wrote:
b) As an extra feature based on conversation with Michael at breakfast this morning you can also do under os-x (unix/darwin) a kill signal to turn recording on.
kill -USR1 19278 {Pick a squeak VM process id}
kill -USR1 19278 {increment the level by one, go to 2} kill -USR1 19278 {increment the level by one, go to 3}
kill -USR2 19278 {turn recording off, and close the file}
Hi John,
Here's one additional suggestion. Rather than dedicating SIGUSR1 and SIGUSR2 to this specific function, you can select what signals to use from the image, and also handle the signals in the image. The OSPP plugin provides the required signal forwarding primitives, so the idea would be to forward SIGUSR1 and SIGUSR2 (or whatever) to semaphores in the image, with processes waiting on the semaphores to do the #setVMStatsTraceMessageSendLevels: calls that control the trace logging.
The reason this is important is that someone else may want to use SIGUSR1 and SIGUSR2 for some other purpose. For example, some pthread libraries on Linux make use of these signals, which would mean that a Linux VM that used pthreads might not work if you steal the signal handlers away from the pthreads library. I think that the svalib on Linux also uses these signals, which would affect somebody who wanted a VM on Linux that ran directly on the VGA display rather than on X window. And who knows about all the sound libraries and so forth. Also, somebody running a Seaside server might want to use SIGUSR1 to signal the server to do an image save (just making this up as a possible example).
Note: I'm afraid that I did not put convenience methods into OSPP for the SIGUSR1 and SIGUSR2 signals (but that's an easy fix), so you would need to specify the actual integer values 10 and 12, as in
startTracingSemaphore := OSProcess accessor forwardSignal: 10. [[startTracingSemaphore wait. (traceLevel < 5) ifTrue: [traceLevel := traceLevel + 1. Smalltalk setVMStatsTraceMessageSendLevels: traceLevel]] repeat] fork
The above is not tested, but you get the idea.
And I should fix up OSP so you can say "OSProcess accessor forwardSigUsr1" instead of "OSProcess accessor forwardSignal: 10".
Dave
David the change set is on ftp://ftp.smalltalkconsulting.com/experimental/JMMRecordMsgSends. 1.cs.zip
If you want to change the logic to invoke what you suggest please do and send me the change set. Having a working example for the Unix VM would be a good thing. The method of interest would be:
Change? Interpreter >>initVmStatsTraceMessageSendLevels vmStatsTraceMessageSendLevels := 0. vmStatsTraceMessageSendStorageFile := 0.
Then consider two sig handlers of your choice. One that tracks the level increment number and increments it by one for each signal and then invokes. Smalltalk setVMStatsTraceMessageSendLevels: theIncrementNumber
The other handler would just reset theIncrementNumber to zero and invoke the setVMStatsTraceMessageSendLevels:
----------
ORIGINAL: *Apologies to people horrified by this piece of code abuses of how self cCode: works and how it interacts with SLANG, however as experimental code things can be a bit hacked*
Interpreter >>initVmStatsTraceMessageSendLevels vmStatsTraceMessageSendLevels := 0. vmStatsTraceMessageSendStorageFile := 0. self cCode: ' { void handleUSR1(int signal); void handleUSR2(int signal);
signal(SIGUSR1, handleUSR1); signal(SIGUSR2, handleUSR2); } } #include <libc.h> #include <signal.h>
void handleUSR1(int signal) { foo->vmStatsTraceMessageSendLevels++; }
void handleUSR2(int signal) { foo->vmStatsTraceMessageSendLevels = 0; if (foo->vmStatsTraceMessageSendStorageFile) fclose(foo->vmStatsTraceMessageSendStorageFile); foo->vmStatsTraceMessageSendStorageFile = 0;
'
On 30-Oct-05, at 10:21 AM, David T. Lewis wrote:
On Sat, Oct 29, 2005 at 09:46:39PM -0700, John M McIntosh wrote:
b) As an extra feature based on conversation with Michael at breakfast this morning you can also do under os-x (unix/darwin) a kill signal to turn recording on.
kill -USR1 19278 {Pick a squeak VM process id}
kill -USR1 19278 {increment the level by one, go to 2} kill -USR1 19278 {increment the level by one, go to 3}
kill -USR2 19278 {turn recording off, and close the file}
Hi John,
Here's one additional suggestion. Rather than dedicating SIGUSR1 and SIGUSR2 to this specific function, you can select what signals to use from the image, and also handle the signals in the image. The OSPP plugin provides the required signal forwarding primitives, so the idea would be to forward SIGUSR1 and SIGUSR2 (or whatever) to semaphores in the image, with processes waiting on the semaphores to do the #setVMStatsTraceMessageSendLevels: calls that control the trace logging.
The reason this is important is that someone else may want to use SIGUSR1 and SIGUSR2 for some other purpose. For example, some pthread libraries on Linux make use of these signals, which would mean that a Linux VM that used pthreads might not work if you steal the signal handlers away from the pthreads library. I think that the svalib on Linux also uses these signals, which would affect somebody who wanted a VM on Linux that ran directly on the VGA display rather than on X window. And who knows about all the sound libraries and so forth. Also, somebody running a Seaside server might want to use SIGUSR1 to signal the server to do an image save (just making this up as a possible example).
Note: I'm afraid that I did not put convenience methods into OSPP for the SIGUSR1 and SIGUSR2 signals (but that's an easy fix), so you would need to specify the actual integer values 10 and 12, as in
startTracingSemaphore := OSProcess accessor forwardSignal: 10. [[startTracingSemaphore wait. (traceLevel < 5) ifTrue: [traceLevel := traceLevel + 1. Smalltalk setVMStatsTraceMessageSendLevels: traceLevel]] repeat] fork
The above is not tested, but you get the idea.
And I should fix up OSP so you can say "OSProcess accessor forwardSigUsr1" instead of "OSProcess accessor forwardSignal: 10".
Dave
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
On Sun, Oct 30, 2005 at 10:44:24AM -0800, John M McIntosh wrote:
David the change set is on ftp://ftp.smalltalkconsulting.com/experimental/JMMRecordMsgSends. 1.cs.zip
If you want to change the logic to invoke what you suggest please do and send me the change set. Having a working example for the Unix VM would be a good thing.
OK, thanks. I'll send a change set as soon as I get a chance (maybe not today though).
Dave
On Sun, Oct 30, 2005 at 10:44:24AM -0800, John M McIntosh wrote:
On 30-Oct-05, at 10:21 AM, David T. Lewis wrote:
Here's one additional suggestion. Rather than dedicating SIGUSR1 and SIGUSR2 to this specific function, you can select what signals to use from the image, and also handle the signals in the image.
David the change set is on ftp://ftp.smalltalkconsulting.com/experimental/JMMRecordMsgSends. 1.cs.zip
If you want to change the logic to invoke what you suggest please do and send me the change set. Having a working example for the Unix VM would be a good thing.
Hi John,
Here are the changes to move the SIGUSR1 and SIGUSR2 signal handlers out of the VM and into the image. Class VMStatsTraceControl implements the signal handlers, which are activated at image startup and deactivated at image shutdown.
Along the way I fixed a bug in #primitiveSetVMStatsTraceMessageSendLevels that was causing my VM to crash when the stats log file was closed then reopened.
I have to mention that I have seen a nasty problem that I don't understand. On two different occasions while I was writing and debugging this, I ended up the stats trace log data being written to my changes file (with horrible results, needless to say). I do not know what the cause was, I don't know how to reproduce it, and I don't know if it's related to the signal handling or something else in the interpreter changes. In any case, be on the lookout for this bug, and save your image rather more often than you might otherwise do.
Other than that, it's rock solid ;)
Dave
From the change set preambles:
VMStatsTraceControl-dtl
Add VMStatsTraceControl to provide the signal handlers for SIGUSR1 and SIGUSR1 controlling VM stats log. Sending a SIGUSR1 signal to the Squeak process increments the logging level, and SIGUSR2 disables logging and closes the file.
Requires OSProcess for the signal handling (but relevant methods can be copied into VMStatsTraceControl if you don't want to require OSP). The signal handling primitive is in OSPP, currently distributed with the Unix VM, or load OSProcessPlugin from SqueakMap.
VMStatsInterpreterChanges-dtl
Interpreter changes to accompany VMStatsTraceControl-dtl. This removes the SIGUSR1 and SIGUSR2 signal handlers from the interpreter so they can be handled in the image.
Load this after JMMRecordMsgSends and JMMRecordMsgSendInterface. Also load VMStatsTraceControl-dtl.
Interpreter changes: - Removed #cCode: (interrupt handlers) from Interpreter>>initVmStatsTraceMessageSendLevels. - Added Add Interpreter>>primitiveGetVMStatsTraceMessageSendLevels. - Added SystemDictionary>>getVMStatsTraceMessageSendLevels - Fixed assignment bug in Interpreter>>primitiveSetVMStatsTraceMessageSendLevels (change '=' to ':=').
David thank you for doing this work, I've put your changesets and my altered changsets on my ftp server. (got to love = versus == issues as always in C, 27 years of practice and I still can get it right). I will remark seeing a Microsoft Ad lately talking about C buffer overflow issues and how MS was *solving* the issue by training their staff, "can you spot the error", and thinking, duh a Smalltalker would call the existing method to do that str concatenation, versus writing a hunk of C code.
I think the issue here (and might suggest you could make the change) is to set a flag on the signal change to avoid a race condition between the interpreter and the signal handler for access to the file handle. I wonder if the file gets closed by the signal as we are doing fprintfs....
Perhaps in
primitiveSetVMStatsTraceMessageSendLevels
only set vmStatsTraceMessageSendLevels to say (-1) if goes to zero and leave vmStatsTraceMessageSendStorageFile alone, don't close the file.
then in printCallStack1OnlyOf if vmStatsTraceMessageSendLevels is < 0 and if vmStatsTraceMessageSendStorageFile is not zero close file and always set vmStatsTraceMessageSendStorageFile & vmStatsTraceMessageSendLevels to zero, and return.
later if we get another set to zero signal, we'll invoke printCallStack1OnlyOf but do nothing or if we get set to N we'll see vmStatsTraceMessageSendStorageFile = 0 and reopen the file.
On 2-Nov-05, at 2:46 PM, David T. Lewis wrote:
I have to mention that I have seen a nasty problem that I don't understand. On two different occasions while I was writing and debugging this, I ended up the stats trace log data being written to my changes file (with horrible results, needless to say). I do not know what the cause was, I don't know how to reproduce it, and I don't know if it's related to the signal handling or something else in the interpreter changes. In any case, be on the lookout for this bug, and save your image rather more often than you might otherwise do.
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
On Wed, Nov 02, 2005 at 05:38:55PM -0800, John M McIntosh wrote:
(got to love = versus == issues as always in C, 27 years of practice and I still can get it right).
Worse than that, I didn't spot it until I looked at the generated C code. So I was staring at the "=" versus ":=" and not seeing it, but when I saw the "==" instead of "=" in C, I noticed it. So maybe that funky left-arrow assignment character isn't such a dumb idea after all ;)
<intermittent irreproducible bug description snipped>
I think the issue here (and might suggest you could make the change) is to set a flag on the signal change to avoid a race condition between the interpreter and the signal handler for access to the file handle. I wonder if the file gets closed by the signal as we are doing fprintfs....
It sure seems like it must be that sort of problem. Only thing is, nothing is being done in the context of the Unix signal handler. By forwarding the Unix signal to a Squeak Semaphore, we are ensuring that the signal handling work is done in the interpreter itself, hence no such race condition should be possible.
Unfortunately, noone has informed the bug of the impossibility of its existence, so it still seems to be happening.
I'll try harder to reproduce this, and see if your suggestion helps.
Dave
On Wed, Nov 02, 2005 at 10:03:25PM -0500, David T. Lewis wrote:
<intermittent irreproducible bug description snipped>
On Wed, Nov 02, 2005 at 05:38:55PM -0800, John M McIntosh wrote:
I think the issue here (and might suggest you could make the change) is to set a flag on the signal change to avoid a race condition between the interpreter and the signal handler for access to the file handle. I wonder if the file gets closed by the signal as we are doing fprintfs....
It sure seems like it must be that sort of problem. Only thing is, nothing is being done in the context of the Unix signal handler. By forwarding the Unix signal to a Squeak Semaphore, we are ensuring that the signal handling work is done in the interpreter itself, hence no such race condition should be possible.
Unfortunately, noone has informed the bug of the impossibility of its existence, so it still seems to be happening.
I'll try harder to reproduce this, and see if your suggestion helps.
John,
I've not been able to reproduce this bug. I set up a shell script to signal Squeak with SIGUSR1 then SIGUSR2 continuously with 100msec delays, then did things in Squeak including filein/out, edit code, etc. The trace logging worked, and I had no further problems.
So... don't worry about the bug, it was probably just something dumb I did in the course of testing an earlier version of my changes.
Dave
John,
This is an updated version of VMStatsTraceControl-dtl for controlling your VM stats logging. It is updated to take advantage of OSP 4.0.1 and OSPP 4.0.1, which provide primitives to identify the (platform-dependent) SIGUSR1 and SIGUSR2 signal numbers. It is backward compatible, using the default values 10 and 12 respectively if the primitives are not available.
It also provides convenience methods VMStatsTraceControl class>>incrSigNum: and VMStatsTraceControl class>>clearSigNum: to control the signals to be monitored.
VMStatsTraceControl-dtl.9.cs.gz is the updated change set. I am also attaching the original (unchanged) VMStatsInterpreterChanges-dtl.cs.gz for completeness.
Dave
David, this code is ok, except for the fact you don't need to check for traceLevel being five since it could increment to infinity and if your stack was that size we would try to print it. However you'd need a class or instance variable somewhere that the other signal can reset to zero so that after stopping this block would restart incrementing from zero again.
On 30-Oct-05, at 10:21 AM, David T. Lewis wrote:
On Sat, Oct 29, 2005 at 09:46:39PM -0700, John M McIntosh wrote:
startTracingSemaphore := OSProcess accessor forwardSignal: 10. [[startTracingSemaphore wait. (traceLevel < 5) ifTrue: [traceLevel := traceLevel + 1. Smalltalk setVMStatsTraceMessageSendLevels: traceLevel]] repeat] fork
-- ======================================================================== === John M. McIntosh johnmci@smalltalkconsulting.com 1-800-477-2659 Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com ======================================================================== ===
squeak-dev@lists.squeakfoundation.org