X-CGP-ClamAV-Result: CLEAN X-VirusScanner: Niversoft's CGPClamav Helper v1.22.2a (ClamAV engine v0.102.2) X-Junk-Score: 0 [] X-KAS-Score: 0 [] From: "Samuel Pelletier" Received: from fortimail.cybercat.ca ([216.13.210.77] verified) by post.selbstdenker.com (CommuniGate Pro SMTP 6.3.3) with ESMTPS id 26033233 for webobjects-dev@wocommunity.org; Wed, 16 Jun 2021 19:58:07 +0200 Received-SPF: none receiver=post.selbstdenker.com; client-ip=216.13.210.77; envelope-from=samuel@samkar.com Received: from smtpclient.apple (modemcable213.203-171.107.mc.videotron.ca [107.171.203.213]) (user=samuel%samkar.com mech=PLAIN bits=0) by fortimail.cybercat.ca with ESMTP id 15GHvjqS002431-15GHvjqT002431 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NO) for ; Wed, 16 Jun 2021 13:57:45 -0400 Content-Type: multipart/alternative; boundary="Apple-Mail=_44BEEE26-3BD9-4FF8-A5AF-6DBF54123FA2" Mime-Version: 1.0 (Mac OS X Mail 14.0 \(3654.100.0.2.22\)) Subject: Re: [WO-DEV] old/invalid :1 relationship value, how the H. possible?!? Date: Wed, 16 Jun 2021 13:57:45 -0400 References: To: WebObjects & WOnder Development In-Reply-To: Message-Id: X-Mailer: Apple Mail (2.3654.100.0.2.22) X-FEAS-AUTH-USER: samuel%samkar.com --Apple-Mail=_44BEEE26-3BD9-4FF8-A5AF-6DBF54123FA2 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 I never looked an the snapshot merging code. You should check it. I suspect that if your object contains uncommitted changes, this may = prevent updating... You seem to rely on EOF change propagation for time sensitive data = propagation. I would suggest to use a more in memory solution and use = EOF to store the data if your need is a high throughput change where = everyone need to see the latest data. I implemented a server with this strategy doing saves in very shorts = methods like this and was able to handle 200-400 requests per seconds = with a single instance on a 2012 mac mini with an SSD : EOEditingContext ec =3D ERXEC.newEditingContext(); GameSession session =3D session(ec); if (session.timeToBeat() =3D=3D null || = session.timeToBeat() !=3D timeToBeat) { session.setTimeToBeat(timeToBeat); ec.saveChanges(); } > Le 16 juin 2021 =C3=A0 09:01, OCsite = a =C3=A9crit : >=20 > Some followup: I have analysed the R/R loops in details and found that >=20 > - the user B saved changes at 11:00:25.220 > - at this moment, there was a user A's R/R loop (which never touched = the relevant data), running from 11:00:24.570 to 11:00:25.548 > - the next user A's R/R loop started at 11:00:38.113, read the = relevant data, did not see the changes of 11:00:25.220 >=20 > In other words, > - at 11:00:25.220, user A's EC was locked; it should not merge the = changes immediately... > - ... but, at 11:00:25.548 the user A's EC was unlocked: at this = moment the 11:00:25.220 changes should be merged into the EC... > - ... which self-evidently did not happen, for in the next R/R loop = started at 11:00:38.113 the 11:00:25.220 changes were still not visible. >=20 > How could that happen? What could prevent the merge at the EC = unlock/RR loop end? >=20 > Thanks for any advice, > OC >=20 >> On 16 Jun 2021, at 6:35, OCsite > wrote: >>=20 >> Matthew, >>=20 >> no luck this way: one instance only, and one OSC = (ERXObjectStoreCoordinatorPool.maxCoordinators=3D1). >>=20 >> Thanks, >> OC >>=20 >>> On 16. 6. 2021, at 2:57, Matthew Ness = > = wrote: >>>=20 >>>=20 >>> On Wed, Jun 16, 2021, at 1:42 AM, OCsite wrote: >>>> Hi there, >>>>=20 >>>> today we have bumped into a weird behaviour which I can't grok. We = got an old/invalid value for a :1 relationship to an important object = (important enough we even added its FK to the modelled locked attributes = aside of the PK; not that it helped any, but thanks to that, we see the = current snapshot values in the database operations). >>>>=20 >>>> 1. user A stored new object into the relationship; since we log all = database operations, we can see for his EC how this happened: >>>>=20 >>>> 11:00:12.995 UPDATE on 'DBAuction' ((uid =3D 1005602) and = (lastValidPriceOfferID =3D 1061694)) -> {lastValidPriceOfferID:1061695} >>>>=20 >>>> The saveChanges operation did not fail and the appropriate R/R loop = did end without a glitch, no exception, no problem at all, at = 11:00:13.036. >>>>=20 >>>> 2. user B changed the object; again, we can see for his EC >>>>=20 >>>> 11:00:25.220 UPDATE on 'DBAuction' ((uid =3D 1005602) and = (lastValidPriceOfferID =3D 1061695)) -> {lastValidPriceOfferID:1061698} >>>>=20 >>>> The saveChanges operation again finished successfully and the = appropriate R/R loop did end all right at 11:00:25.424. >>>>=20 >>>> 3. in a new R/R loop which started at 11:00:40.947, user A read the = value (the very standard way through = storedValueForKey('lastValidPriceOffer') =E2=80=94 which is the one we = observe all the time, modelled as a simple :1 relationship with FK = lastValidPriceOfferID) =E2=80=94, and got the stale object PK:1061695!=20= >>>>=20 >>>> How is it possible that the step 2 did not update values in user = A's EC? Incidentally, to make extra sure we do not get stale values even = if R/R threads happen to overlap, the code uses in the step 3 looks like = this: >>>>=20 >>>> synchronized (alock) { // lock for the DBAuction 1005602 object = (conceptually on PK to lock out all users regardless their ECs) >>>> try { >>>> auction.editingContext().unlock() // so as to process = recent changes from other ECs (thanks, Chuck!) >>>> auction.editingContext().lock() // of course we have = to keep it locked >>>> DBPriceOffer wins=3Dauction.lastValidPriceOffer() // = simply calls storedValueForKey('lastValidPriceOffer') >>>> println "... last valid $wins" >>>>=20 >>>> and this very log shows we have got the old price offer, the one = with PK:1061695. >>>>=20 >>>> I could understand this if user A changed the object to 1061695 and = did not save it (in which case the EC sync would not touch the change; = but then it would be all right, if the change was not saved), but he = very definitely did save the 1061695 successfully in step 1, and never = changed it later (until he got it again =E2=80=94 the old/invalid value! = =E2=80=94 in step 3). >>>>=20 >>>> Can anyone see a scenario which would lead to him seeing still = 1061695 in step 3, regardless that >>>> - he did save it successfully at 11:00:12 and never changed it = later; >>>> - another user did change it to 1061698 and successfully did save = at 11:00:25; >>>> - aside of the extra lock/unlock shown above, there is no manual EC = locking, ECs are auto-locked at R/Rs; >>>> - and besides, even if the extra lock/unlock was not used, the R/R = threads here did not overlap, so the change should be synced all right, = and the user should get 1061698 in the step 3? >>>>=20 >>>> What do I overlook? >>>>=20 >>>> Thanks and all the best, >>>> OC >>>>=20 >>>=20 >>> Hi, >>>=20 >>> How many instances of the application aretypically running? >>>=20 >>> Regards, >>>=20 >>> --=20 >>> Matt >>> https://logicsquad.net >>> https://www.linkedin.com/company/logic-squad/ = --Apple-Mail=_44BEEE26-3BD9-4FF8-A5AF-6DBF54123FA2 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
I never looked an the snapshot merging code. You should check = it.

I suspect = that if your object contains uncommitted changes, this may prevent = updating...

You seem to rely = on EOF change propagation for time sensitive data propagation. I would = suggest to use a more in memory solution and use EOF to store the data = if your need is a high throughput change where everyone need to see the = latest data.

I = implemented a server with this strategy doing saves in very shorts = methods like this and was able to handle 200-400 requests per seconds = with a single instance on a 2012 mac mini with an SSD :
= EOEditingContext ec =3D ERXEC.newEditingContext();
= GameSession session =3D session(ec);
= if (session.timeToBeat() = =3D=3D null || session.timeToBeat() !=3D timeToBeat) = {
= session.setTimeToBeat(timeToBeat);
= ec.saveChanges();
= }


Le 16 juin 2021 =C3=A0 09:01, = OCsite <webobjects-dev@wocommunity.org> a =C3=A9crit = :

Some followup: I have = analysed the R/R loops in details and found that

- the user B saved changes at = 11:00:25.220
- at this moment, there was a user A's = R/R loop (which never touched the relevant data), running = from 11:00:24.570 to 11:00:25.548
- the = next user A's R/R loop started at 11:00:38.113, read the = relevant data, did not see the changes = of 11:00:25.220

In other words,
- at 11:00:25.220, user = A's EC was locked; it should not merge the changes = immediately...
- ... but, at 11:00:25.548 the user = A's EC was unlocked: at this moment the 11:00:25.220 changes should be = merged into the EC...
- ... which self-evidently = did not happen, for in the next R/R loop started at 11:00:38.113 = the 11:00:25.220 changes were still not visible.

How could that happen? What could = prevent the merge at the EC unlock/RR loop end?

Thanks for any advice,
OC

On 16 = Jun 2021, at 6:35, OCsite <webobjects-dev@wocommunity.org> wrote:

Matthew,

no luck this way: one instance only, and one OSC = (ERXObjectStoreCoordinatorPool.maxCoordinators=3D1).

Thanks,
OC

On 16. = 6. 2021, at 2:57, Matthew Ness <webobjects-dev@wocommunity.org> wrote:


On Wed, Jun 16, 2021, at = 1:42 AM, OCsite wrote:
Hi there,

today we have bumped into a weird = behaviour which I can't grok. We got an old/invalid value for a :1 = relationship to an important object (important enough we even added its = FK to the modelled locked attributes aside of the PK; not that it helped = any, but thanks to that, we see the current snapshot values in the = database operations).

1. user A stored new object into the = relationship; since we log all database operations, we can see for his = EC how this happened:

11:00:12.995 = UPDATE on 'DBAuction' ((uid =3D 1005602) and (lastValidPriceOfferID =3D = 1061694)) -> {lastValidPriceOfferID:1061695}

The saveChanges operation did not fail and = the appropriate R/R loop did end without a glitch, no exception, no = problem at all, at 11:00:13.036.

2. user B changed = the object; again, we can see for his EC

11:00:25.220 UPDATE on 'DBAuction' ((uid =3D = 1005602) and (lastValidPriceOfferID =3D 1061695)) -> = {lastValidPriceOfferID:1061698}

The saveChanges operation again finished = successfully and the appropriate R/R loop did end all right = at 11:00:25.424.

3. in a new R/R loop which started = at 11:00:40.947, user A read the value (the very standard way = through storedValueForKey('lastValidPriceOffer') =E2=80=94 which is the one = we observe all the time, modelled as a simple :1 relationship with = FK lastValidPriceOfferID) =E2=80=94, and got the = stale object PK:1061695! 

How is it possible = that the step 2 did not update values in user A's EC? Incidentally, to = make extra sure we do not get stale values even if R/R threads happen to = overlap, the code uses in the step 3 looks like this:

  =   synchronized (alock) = { // lock for the DBAuction 1005602 object (conceptually on PK to lock out all users = regardless their ECs)
    =     try {
    =         auction.editingContext().unlock() // so as to process recent changes = from other ECs (thanks, Chuck!)
    =         auction.editingContext().lock() =   // of = course we have to keep it locked
            = DBPriceOffer = wins=3Dauction.lastValidPriceOffer() // simply calls storedValueForKey('lastValidPriceOffer')
        =     println "... last valid = $wins"

and this very log shows we have got = the old price offer, the one with PK:1061695.

I could understand = this if user A changed the object to 1061695 and did not = save it (in which = case the EC sync would not touch the change; but then it would be all = right, if the change was not saved), but he very definitely did save = the 1061695 successfully in step 1, and never changed it later = (until he got it again =E2=80=94 the old/invalid value! =E2=80=94 in = step 3).

Can anyone see a scenario which would lead to him seeing = still 1061695 in step 3, regardless that
- he did save it successfully at 11:00:12 and never = changed it later;
- another user = did change it to 1061698 and successfully did save = at 11:00:25;
- aside of the = extra lock/unlock shown above, there is no manual EC locking, ECs are = auto-locked at R/Rs;
- and = besides, even if the extra lock/unlock was not used, the R/R = threads here did not overlap, so the change should be synced all right, and the user should get 1061698 in the step 3?

What do I overlook?

Thanks and all the = best,
OC


Hi,

How = many instances of the application aretypically running?

Regards,

-- 
Matt
https://logicsquad.net
https://www.linkedin.com/company/logic-squad/


= --Apple-Mail=_44BEEE26-3BD9-4FF8-A5AF-6DBF54123FA2--