Interrupting process which hangs on recursion
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds: hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11. hanging resume. interruptor resume. Recursion method: Integer>>recursionTest self recursionTest Hanging process produces 7 million contexts on my machine: c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279" But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger. We need to change this logic. Best regards, Denis
Very cool analysis! What would your proposal be in this case? Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com "One cannot do more than one can do."
Awesome Denis!
On 13 Aug 2016, at 10:54, Tudor Girba <tudor@tudorgirba.com> wrote:
Very cool analysis!
What would your proposal be in this case?
Some ideas: - perform logging in a separate process - only log user interrupt once for any given time interval, i.e., while a previous interrupt is being logged, ignore logging for further interrupts. Alternatively: donât log user interrupts. I donât really see the value anyway. Cheers, Max
Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com
"One cannot do more than one can do."
Hi,
On Aug 14, 2016, at 9:14 AM, Max Leske <maxleske@gmail.com> wrote:
Awesome Denis!
On 13 Aug 2016, at 10:54, Tudor Girba <tudor@tudorgirba.com> wrote:
Very cool analysis!
What would your proposal be in this case?
Some ideas:
- perform logging in a separate process - only log user interrupt once for any given time interval, i.e., while a previous interrupt is being logged, ignore logging for further interrupts.
Alternatively: donât log user interrupts. I donât really see the value anyway.
I kind of like the idea of not logging user interrupts. What do others think? Cheers, Doru
Cheers, Max
Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com
"One cannot do more than one can do."
-- www.tudorgirba.com www.feenk.com "Yesterday is a fact. Tomorrow is a possibility. Today is a challenge."
But the slowness comes from printing a too large stack, no ? Why not just limit the size of the stack being printed ?
On 14 Aug 2016, at 09:24, Tudor Girba <tudor@tudorgirba.com> wrote:
Hi,
On Aug 14, 2016, at 9:14 AM, Max Leske <maxleske@gmail.com> wrote:
Awesome Denis!
On 13 Aug 2016, at 10:54, Tudor Girba <tudor@tudorgirba.com> wrote:
Very cool analysis!
What would your proposal be in this case?
Some ideas:
- perform logging in a separate process - only log user interrupt once for any given time interval, i.e., while a previous interrupt is being logged, ignore logging for further interrupts.
Alternatively: donât log user interrupts. I donât really see the value anyway.
I kind of like the idea of not logging user interrupts. What do others think?
Cheers, Doru
Cheers, Max
Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com
"One cannot do more than one can do."
-- www.tudorgirba.com www.feenk.com
"Yesterday is a fact. Tomorrow is a possibility. Today is a challenge."
2016-08-14 10:19 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
But the slowness comes from printing a too large stack, no ? Why not just limit the size of the stack being printed ?
Maybe it is better to limit time which could be spend on log writing. Sometime I guess writing to log itself raises errors and recursions which could be another reason for non working cmd+.. We could limit it for 1 second. And if it is not enough then append extra ~20 contexts from root which will show reason for possible recursion (also limited in time). What you think?
On 16 Aug 2016, at 10:11, Denis Kudriashov <dionisiydk@gmail.com> wrote:
2016-08-14 10:19 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu <mailto:sven@stfx.eu>>: But the slowness comes from printing a too large stack, no ? Why not just limit the size of the stack being printed ?
Maybe it is better to limit time which could be spend on log writing. Sometime I guess writing to log itself raises errors and recursions which could be another reason for non working cmd+.. We could limit it for 1 second. And if it is not enough then append extra ~20 contexts from root which will show reason for possible recursion (also limited in time). What you think?
That sounds like too much magic to me...
So I opened this case 19108 <https://pharo.fogbugz.com/f/cases/19108/Logging-error-stack-should-not-hang-...> and submitted slice which restricts logging time to 100 milliseconds. (it should be enough, look at issue explanation). But also there is some problem with GTDebugger which talk with full stack items instead of visible ones. It slowdown opening on big stack (which is usual for recursion cases). To see problem just open in browser Context>>sender and put counter on sender variable (from suggestion menu). Also disable stack logging by "DebugSession logDebuggerStackToFile: false". Now execute "1 recursionTest" from workspace and after 3 seconds press cmd+.. You will see 11610 calls of "context sender". Interesting that with SpecDebugger it is just 42 calls. 2016-08-16 11:30 GMT+02:00 Max Leske <maxleske@gmail.com>:
On 16 Aug 2016, at 10:11, Denis Kudriashov <dionisiydk@gmail.com> wrote:
2016-08-14 10:19 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
But the slowness comes from printing a too large stack, no ? Why not just limit the size of the stack being printed ?
Maybe it is better to limit time which could be spend on log writing. Sometime I guess writing to log itself raises errors and recursions which could be another reason for non working cmd+.. We could limit it for 1 second. And if it is not enough then append extra ~20 contexts from root which will show reason for possible recursion (also limited in time). What you think?
That sounds like too much magic to me...
Great work, Denis! We have to look at how the GTDebugger works with large stacks. Could you please open an issue for that? Cheers, Doru
On Sep 19, 2016, at 10:36 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
So I opened this case 19108 and submitted slice which restricts logging time to 100 milliseconds. (it should be enough, look at issue explanation).
But also there is some problem with GTDebugger which talk with full stack items instead of visible ones. It slowdown opening on big stack (which is usual for recursion cases). To see problem just open in browser Context>>sender and put counter on sender variable (from suggestion menu). Also disable stack logging by "DebugSession logDebuggerStackToFile: false".
Now execute "1 recursionTest" from workspace and after 3 seconds press cmd+.. You will see 11610 calls of "context sender". Interesting that with SpecDebugger it is just 42 calls.
2016-08-16 11:30 GMT+02:00 Max Leske <maxleske@gmail.com>:
On 16 Aug 2016, at 10:11, Denis Kudriashov <dionisiydk@gmail.com> wrote:
2016-08-14 10:19 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>: But the slowness comes from printing a too large stack, no ? Why not just limit the size of the stack being printed ?
Maybe it is better to limit time which could be spend on log writing. Sometime I guess writing to log itself raises errors and recursions which could be another reason for non working cmd+.. We could limit it for 1 second. And if it is not enough then append extra ~20 contexts from root which will show reason for possible recursion (also limited in time). What you think?
That sounds like too much magic to me...
-- www.tudorgirba.com www.feenk.com "If you can't say why something is relevant, it probably isn't."
2016-09-19 10:44 GMT+02:00 Tudor Girba <tudor@tudorgirba.com>:
Great work, Denis!
We have to look at how the GTDebugger works with large stacks. Could you please open an issue for that?
Done 19109 <https://pharo.fogbugz.com/f/cases/19109/GTDebugger-produces-too-much-context...>
+1 on not logging by default, but when using images as servers and/or running headless it seems that logging interrupts would be desirable. Sven, I think that Pharo already does some truncation of the stacks and frankly IMHO, if you are going to truncate the stack don't bother writing it at all .... Nothing more frustrating that reading down a printed stack only to find the bit that you NEED has been truncated! If there are folks who prefer truncated stacks, then perhaps that needs to be an option as well ... It seems that the debugger in Pharo5.0 truncates the number of frames supplied when you copy the stack as well - I assume it is using the stack logger code that is already truncating stacks :) Dale On 8/14/16 12:24 AM, Tudor Girba wrote:
Hi,
On Aug 14, 2016, at 9:14 AM, Max Leske <maxleske@gmail.com> wrote:
Awesome Denis!
On 13 Aug 2016, at 10:54, Tudor Girba <tudor@tudorgirba.com> wrote:
Very cool analysis!
What would your proposal be in this case? Some ideas:
- perform logging in a separate process - only log user interrupt once for any given time interval, i.e., while a previous interrupt is being logged, ignore logging for further interrupts.
Alternatively: donât log user interrupts. I donât really see the value anyway. I kind of like the idea of not logging user interrupts. What do others think?
Cheers, Doru
Cheers, Max
Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com
"One cannot do more than one can do."
-- www.tudorgirba.com www.feenk.com
"Yesterday is a fact. Tomorrow is a possibility. Today is a challenge."
What is a user log? Stef Le 14/8/16 à 09:24, Tudor Girba a écrit :
Hi,
On Aug 14, 2016, at 9:14 AM, Max Leske <maxleske@gmail.com> wrote:
Awesome Denis!
On 13 Aug 2016, at 10:54, Tudor Girba <tudor@tudorgirba.com> wrote:
Very cool analysis!
What would your proposal be in this case? Some ideas:
- perform logging in a separate process - only log user interrupt once for any given time interval, i.e., while a previous interrupt is being logged, ignore logging for further interrupts.
Alternatively: donât log user interrupts. I donât really see the value anyway. I kind of like the idea of not logging user interrupts. What do others think?
Cheers, Doru
Cheers, Max
Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com
"One cannot do more than one can do."
-- www.tudorgirba.com www.feenk.com
"Yesterday is a fact. Tomorrow is a possibility. Today is a challenge."
Hi, I was referring to the fact that when we press Cmd + . , the halt is being logged in the PharoDebug.log, and this delays the debugger popping up, and one proposal was to not log these direct user actions. Cheers, Doru
On Aug 16, 2016, at 9:41 AM, stepharo <stepharo@free.fr> wrote:
What is a user log?
Stef
Le 14/8/16 à 09:24, Tudor Girba a écrit :
Hi,
On Aug 14, 2016, at 9:14 AM, Max Leske <maxleske@gmail.com> wrote:
Awesome Denis!
On 13 Aug 2016, at 10:54, Tudor Girba <tudor@tudorgirba.com> wrote:
Very cool analysis!
What would your proposal be in this case? Some ideas:
- perform logging in a separate process - only log user interrupt once for any given time interval, i.e., while a previous interrupt is being logged, ignore logging for further interrupts.
Alternatively: donât log user interrupts. I donât really see the value anyway. I kind of like the idea of not logging user interrupts. What do others think?
Cheers, Doru
Cheers, Max
Doru
On Aug 13, 2016, at 10:42 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds:
hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
-- www.tudorgirba.com www.feenk.com
"One cannot do more than one can do."
-- www.tudorgirba.com www.feenk.com
"Yesterday is a fact. Tomorrow is a possibility. Today is a challenge."
-- www.tudorgirba.com www.feenk.com "Being happy is a matter of choice."
2016-08-16 9:50 GMT+02:00 Tudor Girba <tudor@tudorgirba.com>:
Hi,
I was referring to the fact that when we press Cmd + . , the halt is being logged in the PharoDebug.log, and this delays the debugger popping up, and one proposal was to not log these direct user actions.
I would say, this log should include only unhanded exceptions. Anything else like user interrupt or debug action from process browser don't needs to be logged.
Thanks denis. So our discussions were good :) Le 13/8/16 à 10:42, Denis Kudriashov a écrit :
We had discussion on reasons why cmd+. is not always working. I made simple test which shows that VM is not issue. Following code normally stops after 20 seconds: hanging := [1 seconds wait. 1 recursionTest] newProcess. hanging priority: Processor activePriority + 10. interruptor := [ 20 seconds wait. hanging suspend] newProcess. interruptor priority: Processor activePriority + 11.
hanging resume. interruptor resume.
Recursion method: Integer>>recursionTest self recursionTest
Hanging process produces 7 million contexts on my machine:
c := hanging suspendedContext. count := 1. [ c notNil ] whileTrue: [ c := c sender. count := count + 1 ]. count «7395279"
But if you try to debug it by "hanging debug" you will see how it is slow. It's caused by printing stack to file. Interesting that logging is performed before opening debugger. So every time we press cmd+. we are waiting logging to see debugger.
We need to change this logic.
Best regards, Denis
participants (6)
-
Dale Henrichs -
Denis Kudriashov -
Max Leske -
stepharo -
Sven Van Caekenberghe -
Tudor Girba