Re: way too many SELECTs?
Re: way too many SELECTs?
- Subject: Re: way too many SELECTs?
- From: OC <email@hidden>
- Date: Sat, 14 Feb 2015 16:38:07 +0100
Ken,
On 14. 2. 2015, at 16:04, Ken Anderson <email@hidden> wrote:
> This is certainly odd behavior - something else must be going on.
>
> In your example (a) will always happen - EOF will fault in relationships before adding objects to them. But, once that relationship is there, it should stay in that EO until some kind of invalidation happens.
Thanks!
> Any chance you could post all the code?
Afraid not; it would mean the complete application, which is pretty big.
Meantime, I've found that
(a) if I batch-add the price orders, the extra SELECT does not happen;
(b) if I out-comment saving EC, the extra SELECT does not happen (even over many R/R loops);
(c) on the other hand, with a code
===
3.times {
DBPriceOffer o=new DBPriceOffer()
o.price=-1 // just a tag allowing to clean up the mess in the DB
createdBy.editingContext.insertObject(o)
println "WEIRD 17 newo: $o, creator: $createdBy // EC:${o.editingContext()} (FTS:${(System.currentTimeMillis()-o.editingContext().fetchTimestamp())/1000} s)"
o.addObjectToBothSidesOfRelationshipWithKey(createdBy,'user')
println "WEIRD 21"
o.editingContext().saveChanges()
}
System.exit(0) // to keep the mess in DB limited
===
the extra SELECT _does_ happen.
So, at the moment, I am trying to find what happens during a save. I have commented out my validateForSave and my database context delegate (which logs out all adaptor ops in databaseContextWillPerformAdaptorOperations), and the problem still persists.
Far as I can say, (after out-commenting) no code of mine gets called when saving, but still the log looks like this (removed Begin/Commit internal transactions, which, I think, can't help, just decrease the legibility, and removed the list of columns of SELECTs which is long and helps none, I believe):
===
...
WEIRD 17 newo: <DBPriceOffer@823250915 PK:null N /EC:550440296>, creator: <DBUser@484622050 PK:1000008 Name:'cl' T:'5' /EC:550440296> // EC:er.extensions.eof.ERXEC@20cf0d68 (FTS:3649.305 s)
16:24:06.586 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_PRICE_OFFER" t0 WHERE t0."C_CREATOR_ID" = 1000008" withBindings: >
16:24:06.599 DEBUG 185 row(s) processed
WEIRD 21
16:24:06.800 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "VALUES (SELECT UNIQUE FROM "T_PRICE_OFFER")" withBindings: >
16:24:06.801 DEBUG fetch canceled
16:24:06.802 DEBUG 1 row(s) processed
16:24:06.845 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "INSERT INTO "T_PRICE_OFFER"("C_SHEET_CONFIRMED", "C_UID", "C_AMOUNT", "C_PRICE", "C_CREATION_DATE", "C_CREATOR_ID", "C_VALID_OFFER") VALUES (NULL, 1000265, NULL, -1.00, TIMESTAMP '2015-02-14 16:24:06.573', 1000008, false)" withBindings: >
16:24:06.919 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_USER" t0 WHERE t0."C_UID" = 1000008" withBindings: >
16:24:06.921 DEBUG 1 row(s) processed
WEIRD 17 newo: <DBPriceOffer@216355583 PK:null N /EC:550440296>, creator: <DBUser@484622050 PK:1000008 Name:'cl' T:'5' /EC:550440296> // EC:er.extensions.eof.ERXEC@20cf0d68 (FTS:3649.647 s)
16:24:06.930 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_PRICE_OFFER" t0 WHERE t0."C_CREATOR_ID" = 1000008" withBindings: >
16:24:06.941 DEBUG 186 row(s) processed
WEIRD 21
16:24:06.972 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "VALUES (SELECT UNIQUE FROM "T_PRICE_OFFER")" withBindings: >
16:24:06.974 DEBUG fetch canceled
16:24:06.974 DEBUG 1 row(s) processed
16:24:07.021 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "INSERT INTO "T_PRICE_OFFER"("C_SHEET_CONFIRMED", "C_UID", "C_AMOUNT", "C_PRICE", "C_CREATION_DATE", "C_CREATOR_ID", "C_VALID_OFFER") VALUES (NULL, 1000266, NULL, -1.00, TIMESTAMP '2015-02-14 16:24:06.916', 1000008, false)" withBindings: >
16:24:07.090 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_USER" t0 WHERE t0."C_UID" = 1000008" withBindings: >
16:24:07.092 DEBUG 1 row(s) processed
WEIRD 17 newo: <DBPriceOffer@831641327 PK:null N /EC:550440296>, creator: <DBUser@484622050 PK:1000008 Name:'cl' T:'5' /EC:550440296> // EC:er.extensions.eof.ERXEC@20cf0d68 (FTS:3649.819 s)
16:24:07.101 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_PRICE_OFFER" t0 WHERE t0."C_CREATOR_ID" = 1000008" withBindings: >
16:24:07.111 DEBUG 187 row(s) processed
WEIRD 21
16:24:07.147 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "VALUES (SELECT UNIQUE FROM "T_PRICE_OFFER")" withBindings: >
16:24:07.148 DEBUG fetch canceled
16:24:07.148 DEBUG 1 row(s) processed
16:24:07.185 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "INSERT INTO "T_PRICE_OFFER"("C_SHEET_CONFIRMED", "C_UID", "C_AMOUNT", "C_PRICE", "C_CREATION_DATE", "C_CREATOR_ID", "C_VALID_OFFER") VALUES (NULL, 1000267, NULL, -1.00, TIMESTAMP '2015-02-14 16:24:07.088', 1000008, false)" withBindings: >
APPLICATION SHUTDOWN SEQUENCE COMPLETE
===
To be frank, with my limited knowledge of SQL I don't quite get the
VALUES (SELECT UNIQUE FROM "T_PRICE_OFFER")
lines; what's that? Of the SELECT FROM T_USER I am not sure whether it really makes any sense -- why would EOF refetch the user? The rest of lines make sense -- but for repeating the SELECT FROM T_PRICE_OFFER...
I wonder, what might be the culprit? Note that if the save itself does not happen (the same code as above without "o.editingContext().saveChanges()"), the SELECT is not repeated...
Thanks a lot,
OC
> On Feb 14, 2015, at 8:24 AM, OC <email@hidden> wrote:
>
>> Hello there,
>>
>> as Alice said, it gets couriouser and couriouser. I am now logging SQL, and -- at least to me -- it seems my application is SELECTing way too often.
>>
>> The code is still related to the price offers of my previous posts; this time though I am using the default EC and I am not setting fetchTimestamp.
>>
>> I am creating new objects in an entity DBPriceOffer and adding them to 1:N relationship of an entity DBUser -- all of them to the same user.
>>
>> Now, what I would (naïvely?) assume is that
>> (a) the first time this happens, the user's price offers _might be_ fetched (not necessarily, but possibly)
>> (b) nevertheless, when they _are_ once fetched into the EC, they won't be re-fetched anytime soon, for EC caches them and EOF does not make unnecessary roundtrips to the DB.
>>
>> They get re-fetched though -- each sweet time again, with the same EC, no fetchTimestamp. My app never refaults nor refreshes anything. There's about 95 % free heap, so there should be no flushing of soft caches, if WO uses them at all. My current code looks like this:
>>
>> ===
>> DBPriceOffer o=new DBPriceOffer()
>> createdBy.editingContext.insertObject(o)
>> ...
>> println "WEIRD 27 newo: $o, creator: $createdBy // EC:${o.editingContext()} (FTS:${(System.currentTimeMillis()-o.editingContext().fetchTimestamp())/1000} s)"
>> o.addObjectToBothSidesOfRelationshipWithKey(createdBy,'user')
>> //createdBy.addObjectToBothSidesOfRelationshipWithKey(o,'priceOffers') // tried this too, works precisely same way
>> println "WEIRD 31
>> ===
>>
>> and adding price offers through this code _always_ re-fetches the user's relationship into which they are being added:
>>
>> ===
>> WEIRD 27 newo: <DBPriceOffer@1247321477 PK:null N /EC:176991315>, creator: <DBUser@2069151341 PK:1000008 Name:'cl' /EC:176991315> // EC:er.extensions.eof.ERXEC@a8cac53 (FTS:3996.348 s)
>> 14:09:16.912 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_PRICE_OFFER" t0 WHERE t0."C_CREATOR_ID" = 1000008" withBindings: >
>> 14:09:16.922 DEBUG 179 row(s) processed
>> WEIRD 31
>> ...
>> WEIRD 27 newo: <DBPriceOffer@81493054 PK:null N /EC:176991315>, creator: <DBUser@2069151341 PK:1000008 Name:'cl' /EC:176991315> // EC:er.extensions.eof.ERXEC@a8cac53 (FTS:4001.53 s)
>> 14:09:22.090 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_PRICE_OFFER" t0 WHERE t0."C_CREATOR_ID" = 1000008" withBindings: >
>> 14:09:22.099 DEBUG 180 row(s) processed
>> WEIRD 31
>> ...
>> WEIRD 27 newo: <DBPriceOffer@1879220176 PK:null N /EC:176991315>, creator: <DBUser@2069151341 PK:1000008 Name:'cl /EC:176991315> // EC:er.extensions.eof.ERXEC@a8cac53 (FTS:4006.075 s)
>> 14:09:26.635 DEBUG evaluateExpression: <com.webobjects.jdbcadaptor.FrontbasePlugIn$FrontbaseExpression: "SELECT ... FROM "T_PRICE_OFFER" t0 WHERE t0."C_CREATOR_ID" = 1000008" withBindings: >
>> 14:09:26.643 DEBUG 181 row(s) processed
>> WEIRD 31
>> ...
>> ===
>>
>> and so forth: whenever I add a new price offer into the same user's 1:N relationship, the price offers of that user get re-fetched again.
>>
>> I'm flabbergasted. Is this the normal WebObjects (or, rather, EOF) behaviour? Am I missing something of importance?
>>
>> Thanks,
>> OC
>>
>>
>> _______________________________________________
>> Do not post admin requests to the list. They will be ignored.
>> Webobjects-dev mailing list (email@hidden)
>> Help/Unsubscribe/Update your Subscription:
>>
>> This email sent to email@hidden
>
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden