Windows Time millisecondClockValue (system start vs. image start)

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Windows Time millisecondClockValue (system start vs. image start)

Nicolai Hess-3-2
Hi,

a call to
Time millisecondClockValue
gives the current milliseconds since the image started. Did this change ?
I have a windows squeak 4.4 VM where it gave the uptime of the system (on windows).

Background:
HandMorph generates some MouseOver and/or MouseMove events, and if the
timeStamp value is not set, it sets it to Time millisecondClockValue, but the "real" events have
a time stamp of "milliseconds since system was booted".

So, now it can happen that you have a real event (mouse click) at timeStamp (msecs since boot up)
3000000
and afterwards a generated mouseOver event with a time stamp since image startup
2000000 (if the image started ~15 min after system boot).
That is, a later event as a lower time stamp. This will disturb the event handling in
HandMorph>>#handleEvent: from:

Somehow, (after having the image running for a long time ? I don't know). The time stamp
for the generated events is allways much bigger than for the system events, and this
will make it impossible to detect double-click events.


thanks
nicolai



Reply | Threaded
Open this post in threaded view
|

RE: Windows Time millisecondClockValue (system start vs. image start)

Henrik Nergaard

Hmm.

ActiveHand lastEvent “"[(798@340) mouseOver SHIFT nil nil]"

ActiveHand instVarNamed: #lastEventBuffer "#(1 148008281 659 126 0 0 1 1)" “Timestamp is there, second element”

                             

I cannot see that the stamp is ever 0 from a raw event polled, and I guess that will (should) never happen?

Ie; in HandMorph >> generateMouseEvent: line 15 “stamp = 0 ifTrue: [ stamp := Time milisecondClockValue ]” is dead/wrong code?

 

So I guess that somewhere along the event dispatching/processing (after he event has been moved from the raw buffer into a MorphicEvent subclass object) things are copied/translated without keeping the original timestamp intact.

I found at least two places that causes the timestamp to be lost:

               MouseEvent >> asMoueMove (sets a new timestamp using Time)

              MouseEvent >> asMouseOver

 

I think there are two bugs here

1)     VM clock can differ from Image clock

2)     Translating one event from another do not keep the original timestamp

 

Best regards,

Henrik

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Sunday, August 7, 2016 3:57 PM
To: Pharo Development List <[hidden email]>; The general-purpose Squeak developers list <[hidden email]>
Subject: [squeak-dev] Windows Time millisecondClockValue (system start vs. image start)

 

Hi,

a call to

Time millisecondClockValue

gives the current milliseconds since the image started. Did this change ?

I have a windows squeak 4.4 VM where it gave the uptime of the system (on windows).

Background:

HandMorph generates some MouseOver and/or MouseMove events, and if the

timeStamp value is not set, it sets it to Time millisecondClockValue, but the "real" events have

a time stamp of "milliseconds since system was booted".


So, now it can happen that you have a real event (mouse click) at timeStamp (msecs since boot up)
3000000

and afterwards a generated mouseOver event with a time stamp since image startup

2000000 (if the image started ~15 min after system boot).

That is, a later event as a lower time stamp. This will disturb the event handling in

HandMorph>>#handleEvent: from:

Somehow, (after having the image running for a long time ? I don't know). The time stamp

for the generated events is allways much bigger than for the system events, and this

will make it impossible to detect double-click events.

 

thanks

nicolai



Reply | Threaded
Open this post in threaded view
|

Re: Windows Time millisecondClockValue (system start vs. image start)

Nicolai Hess-3-2


2016-08-07 17:18 GMT+02:00 Henrik Nergaard <[hidden email]>:

Hmm.

ActiveHand lastEvent “"[(798@340) mouseOver SHIFT nil nil]"

ActiveHand instVarNamed: #lastEventBuffer "#(1 148008281 659 126 0 0 1 1)" “Timestamp is there, second element”

                             

I cannot see that the stamp is ever 0 from a raw event polled, and I guess that will (should) never happen?

Ie; in HandMorph >> generateMouseEvent: line 15 “stamp = 0 ifTrue: [ stamp := Time milisecondClockValue ]” is dead/wrong code?

 

So I guess that somewhere along the event dispatching/processing (after he event has been moved from the raw buffer into a MorphicEvent subclass object) things are copied/translated without keeping the original timestamp intact.

I found at least two places that causes the timestamp to be lost:

               MouseEvent >> asMoueMove (sets a new timestamp using Time)

              MouseEvent >> asMouseOver


Yes, that is what I meant by generating mousemove/mouseover events.
For example, if you put
Transcript show:{ evt type. evt timeStamp . firstClickTime} ;cr.

at top of method handleEvent:from:

and click (just click no movement) on the title pane of a system window, you'll see a alot of
#(#mouseMove 9128631 12518171)
Transcript entries

The entries look like they are new events, but I think they are just generated from the last real event , but with a new time stamp.
 

 

I think there are two bugs here

1)     VM clock can differ from Image clock

2)     Translating one event from another do not keep the original timestamp

 

Best regards,

Henrik

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Sunday, August 7, 2016 3:57 PM
To: Pharo Development List <[hidden email]>; The general-purpose Squeak developers list <[hidden email]>
Subject: [squeak-dev] Windows Time millisecondClockValue (system start vs. image start)

 

Hi,

a call to

Time millisecondClockValue

gives the current milliseconds since the image started. Did this change ?

I have a windows squeak 4.4 VM where it gave the uptime of the system (on windows).

Background:

HandMorph generates some MouseOver and/or MouseMove events, and if the

timeStamp value is not set, it sets it to Time millisecondClockValue, but the "real" events have

a time stamp of "milliseconds since system was booted".


So, now it can happen that you have a real event (mouse click) at timeStamp (msecs since boot up)
3000000

and afterwards a generated mouseOver event with a time stamp since image startup

2000000 (if the image started ~15 min after system boot).

That is, a later event as a lower time stamp. This will disturb the event handling in

HandMorph>>#handleEvent: from:

Somehow, (after having the image running for a long time ? I don't know). The time stamp

for the generated events is allways much bigger than for the system events, and this

will make it impossible to detect double-click events.

 

thanks

nicolai







Reply | Threaded
Open this post in threaded view
|

Re: Windows Time millisecondClockValue (system start vs. image start)

marcel.taeumel
Nicolai Hess-3-2 wrote
2016-08-07 17:18 GMT+02:00 Henrik Nergaard <[hidden email]>:

> Hmm.
>
> ActiveHand lastEvent “"[(798@340) mouseOver SHIFT nil nil]"
>
> ActiveHand instVarNamed: #lastEventBuffer "#(1 148008281 659 126 0 0 1 1)"
> “Timestamp is there, second element”
>
>
>
> I cannot see that the stamp is ever 0 from a raw event polled, and I guess
> that will (should) never happen?
>
> Ie; in HandMorph >> generateMouseEvent: line 15 “stamp = 0 ifTrue: [ stamp
> := Time milisecondClockValue ]” is dead/wrong code?
>
>
>
> So I guess that somewhere along the event dispatching/processing (after he
> event has been moved from the raw buffer into a MorphicEvent subclass
> object) things are copied/translated without keeping the original timestamp
> intact.
>
> I found at least two places that causes the timestamp to be lost:
>
>                MouseEvent >> asMoueMove (sets a new timestamp using Time)
>
>               MouseEvent >> asMouseOver
>

Yes, that is what I meant by generating mousemove/mouseover events.
For example, if you put
Transcript show:{ evt type. evt timeStamp . firstClickTime} ;cr.

at top of method handleEvent:from:

and click (just click no movement) on the title pane of a system window,
you'll see a alot of
#(#mouseMove 9128631 12518171)
Transcript entries

The entries look like they are new events, but I think they are just
generated from the last real event , but with a new time stamp.


>
>
> I think there are two bugs here
>
> 1)     VM clock can differ from Image clock
>
> 2)     Translating one event from another do not keep the original
> timestamp
>
>
>
> Best regards,
>
> Henrik
>
>
>
>
>
> *From:* [hidden email] [mailto:
> [hidden email]] *On Behalf Of *Nicolai Hess
> *Sent:* Sunday, August 7, 2016 3:57 PM
> *To:* Pharo Development List <[hidden email]>; The
> general-purpose Squeak developers list <squeak-dev@lists.
> squeakfoundation.org>
> *Subject:* [squeak-dev] Windows Time millisecondClockValue (system start
> vs. image start)
>
>
>
> Hi,
>
> a call to
>
> Time millisecondClockValue
>
> gives the current milliseconds since the image started. Did this change ?
>
> I have a windows squeak 4.4 VM where it gave the uptime of the system (on
> windows).
>
> Background:
>
> HandMorph generates some MouseOver and/or MouseMove events, and if the
>
> timeStamp value is not set, it sets it to Time millisecondClockValue, but
> the "real" events have
>
> a time stamp of "milliseconds since system was booted".
>
>
> So, now it can happen that you have a real event (mouse click) at
> timeStamp (msecs since boot up)
> 3000000
>
> and afterwards a generated mouseOver event with a time stamp since image
> startup
>
> 2000000 (if the image started ~15 min after system boot).
>
> That is, a later event as a lower time stamp. This will disturb the event
> handling in
>
> HandMorph>>#handleEvent: from:
>
> Somehow, (after having the image running for a long time ? I don't know).
> The time stamp
>
> for the generated events is allways much bigger than for the system
> events, and this
>
> will make it impossible to detect double-click events.
>
> see issue
> https://pharo.fogbugz.com/f/cases/18859
>
> and
> http://stackoverflow.com/questions/38700587/double-
> click-highlight-selection-in-pharo-5-0
>
>
>
> thanks
>
> nicolai
>
>
>
>
Hi Nicolas,

event time stamps have been broken in the Windows VM for a long time. See here:
http://forum.world.st/win32-Morphic-event-timeStamp-bug-td4824244.html

Best,
Marcel
Reply | Threaded
Open this post in threaded view
|

Re: Windows Time millisecondClockValue (system start vs. image start)

Nicolai Hess-3-2


2016-08-07 18:13 GMT+02:00 marcel.taeumel <[hidden email]>:
Nicolai Hess-3-2 wrote
> 2016-08-07 17:18 GMT+02:00 Henrik Nergaard &lt;

> henrik.nergaard@

> &gt;:
>
>> Hmm.
>>
>> ActiveHand lastEvent “"[(798@340) mouseOver SHIFT nil nil]"
>>
>> ActiveHand instVarNamed: #lastEventBuffer "#(1 148008281 659 126 0 0 1
>> 1)"
>> “Timestamp is there, second element”
>>
>>
>>
>> I cannot see that the stamp is ever 0 from a raw event polled, and I
>> guess
>> that will (should) never happen?
>>
>> Ie; in HandMorph >> generateMouseEvent: line 15 “stamp = 0 ifTrue: [
>> stamp
>> := Time milisecondClockValue ]” is dead/wrong code?
>>
>>
>>
>> So I guess that somewhere along the event dispatching/processing (after
>> he
>> event has been moved from the raw buffer into a MorphicEvent subclass
>> object) things are copied/translated without keeping the original
>> timestamp
>> intact.
>>
>> I found at least two places that causes the timestamp to be lost:
>>
>>                MouseEvent >> asMoueMove (sets a new timestamp using Time)
>>
>>               MouseEvent >> asMouseOver
>>
>
> Yes, that is what I meant by generating mousemove/mouseover events.
> For example, if you put
> Transcript show:{ evt type. evt timeStamp . firstClickTime} ;cr.
>
> at top of method handleEvent:from:
>
> and click (just click no movement) on the title pane of a system window,
> you'll see a alot of
> #(#mouseMove 9128631 12518171)
> Transcript entries
>
> The entries look like they are new events, but I think they are just
> generated from the last real event , but with a new time stamp.
>
>
>>
>>
>> I think there are two bugs here
>>
>> 1)     VM clock can differ from Image clock
>>
>> 2)     Translating one event from another do not keep the original
>> timestamp
>>
>>
>>
>> Best regards,
>>
>> Henrik
>>
>>
>>
>>
>>
>> *From:*

> squeak-dev-bounces@.squeakfoundation

>  [mailto:
>>

> squeak-dev-bounces@.squeakfoundation

> ] *On Behalf Of *Nicolai Hess
>> *Sent:* Sunday, August 7, 2016 3:57 PM
>> *To:* Pharo Development List &lt;

> pharo-dev@.pharo

> &gt;; The
>> general-purpose Squeak developers list &lt;squeak-dev@lists.
> &gt; squeakfoundation.org>
>> *Subject:* [squeak-dev] Windows Time millisecondClockValue (system start
>> vs. image start)
>>
>>
>>
>> Hi,
>>
>> a call to
>>
>> Time millisecondClockValue
>>
>> gives the current milliseconds since the image started. Did this change ?
>>
>> I have a windows squeak 4.4 VM where it gave the uptime of the system (on
>> windows).
>>
>> Background:
>>
>> HandMorph generates some MouseOver and/or MouseMove events, and if the
>>
>> timeStamp value is not set, it sets it to Time millisecondClockValue, but
>> the "real" events have
>>
>> a time stamp of "milliseconds since system was booted".
>>
>>
>> So, now it can happen that you have a real event (mouse click) at
>> timeStamp (msecs since boot up)
>> 3000000
>>
>> and afterwards a generated mouseOver event with a time stamp since image
>> startup
>>
>> 2000000 (if the image started ~15 min after system boot).
>>
>> That is, a later event as a lower time stamp. This will disturb the event
>> handling in
>>
>> HandMorph>>#handleEvent: from:
>>
>> Somehow, (after having the image running for a long time ? I don't know).
>> The time stamp
>>
>> for the generated events is allways much bigger than for the system
>> events, and this
>>
>> will make it impossible to detect double-click events.
>>
>> see issue
>> https://pharo.fogbugz.com/f/cases/18859
>>
>> and
>> http://stackoverflow.com/questions/38700587/double-
>> click-highlight-selection-in-pharo-5-0
>>
>>
>>
>> thanks
>>
>> nicolai
>>
>>
>>
>>

Hi Nicolas,

event time stamps have been broken in the Windows VM for a long time. See
here:
http://forum.world.st/win32-Morphic-event-timeStamp-bug-td4824244.html

Best,
Marcel


Hi, Marcel, yes I saw that thread, we should *bump* it again. You solution was to modify the event time stamp to use the same milliseconds-since-image-start, right?

I too was confused about the ioMSecs implementation in sqWin32Windows with timeGetTime() vs. the one from sqWin32Heartbeat.c
It seems the windows vm uses the one from the heartbeat, but I couldn't find where this was set, did you find it out?
 



--
View this message in context: http://forum.world.st/Windows-Time-millisecondClockValue-system-start-vs-image-start-tp4909842p4909869.html
Sent from the Squeak - Dev mailing list archive at Nabble.com.




Reply | Threaded
Open this post in threaded view
|

Re: Windows Time millisecondClockValue (system start vs. image start)

marcel.taeumel
Nicolai Hess-3-2 wrote
2016-08-07 18:13 GMT+02:00 marcel.taeumel <[hidden email]>:

> Nicolai Hess-3-2 wrote
> > 2016-08-07 17:18 GMT+02:00 Henrik Nergaard <
>
> > henrik.nergaard@
>
> > >:
> >
> >> Hmm.
> >>
> >> ActiveHand lastEvent “"[(798@340) mouseOver SHIFT nil nil]"
> >>
> >> ActiveHand instVarNamed: #lastEventBuffer "#(1 148008281 659 126 0 0 1
> >> 1)"
> >> “Timestamp is there, second element”
> >>
> >>
> >>
> >> I cannot see that the stamp is ever 0 from a raw event polled, and I
> >> guess
> >> that will (should) never happen?
> >>
> >> Ie; in HandMorph >> generateMouseEvent: line 15 “stamp = 0 ifTrue: [
> >> stamp
> >> := Time milisecondClockValue ]” is dead/wrong code?
> >>
> >>
> >>
> >> So I guess that somewhere along the event dispatching/processing (after
> >> he
> >> event has been moved from the raw buffer into a MorphicEvent subclass
> >> object) things are copied/translated without keeping the original
> >> timestamp
> >> intact.
> >>
> >> I found at least two places that causes the timestamp to be lost:
> >>
> >>                MouseEvent >> asMoueMove (sets a new timestamp using
> Time)
> >>
> >>               MouseEvent >> asMouseOver
> >>
> >
> > Yes, that is what I meant by generating mousemove/mouseover events.
> > For example, if you put
> > Transcript show:{ evt type. evt timeStamp . firstClickTime} ;cr.
> >
> > at top of method handleEvent:from:
> >
> > and click (just click no movement) on the title pane of a system window,
> > you'll see a alot of
> > #(#mouseMove 9128631 12518171)
> > Transcript entries
> >
> > The entries look like they are new events, but I think they are just
> > generated from the last real event , but with a new time stamp.
> >
> >
> >>
> >>
> >> I think there are two bugs here
> >>
> >> 1)     VM clock can differ from Image clock
> >>
> >> 2)     Translating one event from another do not keep the original
> >> timestamp
> >>
> >>
> >>
> >> Best regards,
> >>
> >> Henrik
> >>
> >>
> >>
> >>
> >>
> >> *From:*
>
> > squeak-dev-bounces@.squeakfoundation
>
> >  [mailto:
> >>
>
> > squeak-dev-bounces@.squeakfoundation
>
> > ] *On Behalf Of *Nicolai Hess
> >> *Sent:* Sunday, August 7, 2016 3:57 PM
> >> *To:* Pharo Development List <
>
> > pharo-dev@.pharo
>
> > >; The
> >> general-purpose Squeak developers list <squeak-dev@lists.
> > > squeakfoundation.org>
> >> *Subject:* [squeak-dev] Windows Time millisecondClockValue (system start
> >> vs. image start)
> >>
> >>
> >>
> >> Hi,
> >>
> >> a call to
> >>
> >> Time millisecondClockValue
> >>
> >> gives the current milliseconds since the image started. Did this change
> ?
> >>
> >> I have a windows squeak 4.4 VM where it gave the uptime of the system
> (on
> >> windows).
> >>
> >> Background:
> >>
> >> HandMorph generates some MouseOver and/or MouseMove events, and if the
> >>
> >> timeStamp value is not set, it sets it to Time millisecondClockValue,
> but
> >> the "real" events have
> >>
> >> a time stamp of "milliseconds since system was booted".
> >>
> >>
> >> So, now it can happen that you have a real event (mouse click) at
> >> timeStamp (msecs since boot up)
> >> 3000000
> >>
> >> and afterwards a generated mouseOver event with a time stamp since image
> >> startup
> >>
> >> 2000000 (if the image started ~15 min after system boot).
> >>
> >> That is, a later event as a lower time stamp. This will disturb the
> event
> >> handling in
> >>
> >> HandMorph>>#handleEvent: from:
> >>
> >> Somehow, (after having the image running for a long time ? I don't
> know).
> >> The time stamp
> >>
> >> for the generated events is allways much bigger than for the system
> >> events, and this
> >>
> >> will make it impossible to detect double-click events.
> >>
> >> see issue
> >> https://pharo.fogbugz.com/f/cases/18859
> >>
> >> and
> >> http://stackoverflow.com/questions/38700587/double-
> >> click-highlight-selection-in-pharo-5-0
> >>
> >>
> >>
> >> thanks
> >>
> >> nicolai
> >>
> >>
> >>
> >>
>
> Hi Nicolas,
>
> event time stamps have been broken in the Windows VM for a long time. See
> here:
> http://forum.world.st/win32-Morphic-event-timeStamp-bug-td4824244.html
>
> Best,
> Marcel
>
>
Hi, Marcel, yes I saw that thread, we should *bump* it again. You solution
was to modify the event time stamp to use the same
milliseconds-since-image-start, right?

I too was confused about the ioMSecs implementation in sqWin32Windows with
timeGetTime() vs. the one from sqWin32Heartbeat.c
It seems the windows vm uses the one from the heartbeat, but I couldn't
find where this was set, did you find it out?


>
>
>
> --
> View this message in context: http://forum.world.st/Windows-
> Time-millisecondClockValue-system-start-vs-image-start-
> tp4909842p4909869.html
> Sent from the Squeak - Dev mailing list archive at Nabble.com.
>
>
Hi Nicolai,

Windows' message (MSG) structs provide timestamps relative to OS startup. If we want to have Squeak startup, we have to remember the offset on Squeak startup and then apply it to every keyboard/mouse event timestamp when preparing Squeak's data structures.

We should not just use a mixture of ioMicroMSecs() and MSG->time in sqWin32Window.c meaning that we should "normalize" MSG->time because ioMicroMSecs is normalized to Squeak startup time, too.

Yes, the Windows VM uses a heartbeat thread.

So, there is sqWin32Time.c and sqWin32Heartbeat.c. Both define ioMicroMSecs() and ioMSecs(). sqWin32Time.c has the check "#if !STACKVM", which means the interpreter VM, I think. See, for example "spursrc\vm\interp.h":

...
35 #define STACKVM 1
36 #define SPURVM 1
37 #define COGVM 1
...

So, we have to fix sqWin32Window.c. Look for all "msg->time" and apply the Squeak-Startup-Offset. Sure, we could just use ioMicroMSecs() but it seems awkward since we have the exact time in the MSG* struct provided by the Windows platform.

To check if it works, just restart the VM, move the mouse and evaluate "ActiveHand lastEvent timeStamp". It should be only a few seconds, that is a few thousand milliseconds (~5000).

Event synthesis *in* Squeak uses "Time eventMilliseconds", which calls ioMSecs(). Not sure why not ioMicroMSecs(). Maybe it is related to the Chronology/Timezone discussion a few weeks/month ago. See senders of #eventMilliseconds and browse EventSensor and HandMorph to find out more about when and why to synthesize user input events in Squeak.

Hmm... if you hunt down primitive 135, which is called in Time class >> #eventMillisecondClock, you end up in cointerp.c:

...
static void
primitiveMillisecondClock(void)
{   DECL_MAYBE_SQ_GLOBAL_STRUCT
    sqInt oop;
    char *sp;

        /* begin pop:thenPush: */
        oop = ((((ioMSecs()) & MillisecondClockMask) << 3) | 1);
        longAtput((sp = GIV(stackPointer) + ((1 - 1) * BytesPerWord)), oop);
        GIV(stackPointer) = sp;
}
...

So, there is "... ((((ioMSecs()) & MillisecondClockMask) << 3) | 1) ..." to be used for Squeak's event synthesis. At the time of writing, there seems to be to single method in sqWin32Heartbeat.c that provides that number?

We have:

...
long ioMSecs() { return millisecondClock; }
long ioMicroMSecs(void) { return microToMilliseconds(ioUTCMicrosecondsNow());}
...

to be used in sqWin32Window.c. Hmmm.... Maybe these two are identical?

microToMilliseconds(ioUTCMicrosecondsNow());

((((ioMSecs()) & MillisecondClockMask) << 3) | 1)

Anyway, I think there might be two bugs in sqWin32Window.c
1) msg->time needs to apply the Squeak-startup offset or use ioMicroMSecs() ??
2) recordDragDropEvent(..) should use the same timestamp as all other events ??

Hmmm....

Best,
Marcel