Followup: sloooow select, EOF-level somewhere?!?
Followup: sloooow select, EOF-level somewhere?!?
- Subject: Followup: sloooow select, EOF-level somewhere?!?
- From: OC <email@hidden>
- Date: Mon, 09 Mar 2015 15:17:26 +0100
Hmmm.... what's even more curious is that those SELECTs did happen _pretty long after_ appropriate request processing did finish (more precisely, after application.sleep was called). I am logging R/R loops in application awake/sleep; and the log looks like this (no occurrence of the same worker thread meantime nor later, does not seem it was re-assigned):
===
////// R/R loop #14 WorkerThread5 started at 11:16:48.022 9.3.
////// R/R loop #14 WorkerThread5 done at 11:16:48.074 took 0.053 s
...
////// R/R loop #19 WorkerThread13 started at 11:17:16.709 9.3.
... this is the only non-trivial R/R loop, saved some changes into the DBAuction (uid = 1000706) -- others either SELECTed or did not even that ...
////// R/R loop #19 WorkerThread13 done at 11:17:18.491 took 1.782 s
...
////// R/R loop #25 WorkerThread14 started at 11:25:40.688 9.3.
////// R/R loop #25 WorkerThread14 done at 11:25:42.835 took 2.147 s
...
////// R/R loop #28 WorkerThread8 started at 11:26:15.830 9.3.
////// R/R loop #28 WorkerThread8 done at 11:26:15.928 took 0.098 s
...
////// R/R loop #30 WorkerThread4 started at 11:26:26.175 9.3.
////// R/R loop #30 WorkerThread4 done at 11:26:26.264 took 0.089 s
...
////// R/R loop #33 WorkerThread7 started at 11:26:35.037 9.3.
////// R/R loop #33 WorkerThread7 done at 11:26:37.647 took 2.611 s
...
11:27:13.916 INFO "DBAuction"@2111204009 expression took 114 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread14]
11:29:10.676 INFO "DBAuction"@2111204009 expression took 188 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread7]
11:29:16.320 INFO "DBAuction"@2111204009 expression took 431 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread13]
11:38:22.783 INFO "DBAuction"@2111204009 expression took 53 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread8]
11:48:33.164 INFO "DBAuction"@2111204009 expression took 85 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread4]
11:49:03.859 INFO "DBAuction"@2111204009 expression took 65 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread4]
11:53:10.383 INFO "DBAuction"@2111204009 expression took 135 ms: SELECT ... FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread5]
===
Darn. Does _that_ make any sense?!?
Thanks,
OC
On 9. 3. 2015, at 14:05, OC <email@hidden> wrote:
> Hello there,
>
> using "ERXAdaptorChannelDelegate.sqlLogging", I am getting pretty often slow selects. The select is shown below, but it does not seem to me the database would be the culprit -- I have tried the very same SELECT repeatedly directly in the FrontBaseManager, and I am getting consistently fetch times around 0.005-0.006 s.
>
> Nevertheless, at the ERXAdaptorChannelDelegate level, I am getting more than 0.1 s, up to a terrible half second!
>
> What might be the culprit, and how to cure that? Well there's a lot of columns, but still, _half a second_? And none of them contains lots of data; most of the columns are NULLs; the strings are all under 100 characters; there are three BLOBs -- 141 B, 1 KB and 2.7 KB: all in all, perhaps 5 KB for the complete row. At that, I could stomach 0.1 s perhaps, but hardly 0.431.
>
> It is the FrontBase server (5.2.1g 64-bit), if it is relevant information, running in Mac OS X 10.6.8 10K549, Java 1.6.0_65.
>
> Does it make any sense? And, more importantly, can I help it in my code somehow that such abominations do not happen anymore?
>
> Thanks a lot,
> OC
>
> ===
> 11:29:16.320 INFO "DBAuction"@2111204009 expression took 431 ms: SELECT t0."C_COMM_ALLOW_DEMAND_MIN", t0."C_COMM_ALLOW_OFFER_MIN", t0."C_ALLOWS_PRIVATE_LIMITS", t0."C_AMOUNT_DECIMAL_PLACES", t0."C_AMOUNT_UNIT", t0."C_ARCHIVATION_DATE", t0."C_ARCHIVED_CONTENTS", t0."DC_ATTACH_1000002", t0."C_AUCTION_BLOCKED", t0."C_AUCTION_IS_AUTHORIZED", t0."C_AUCTION_IS_CREATED", t0."C_AUCTION_IS_PUBLISHED", t0."C_AUCTION_IS_SENT", t0."C_AUCTION_SEQ", t0."C_AUCTION_START_DELAY_MINUTES", t0."C_AUCTION_TYPE", t0."C_AUTOMATIC_FIRST_STEP_DELAY", t0."C_AUTOMATIC_NEXT_STEP_DELAY", t0."C_AUTOMATIC_OFFER_DELAY", t0."C_AUTOMATIC_PRICE_STEP", t0."C_CANCELLED", t0."DC_CENTRALIZOVANA_1000009", t0."DC_CETNOST_ZALOH_1000009", t0."DC_CHARAKTER_ODBERU_1000015", t0."DC_CISLOTEST_1000002", t0."DC_COMMODITY_1000006", t0."C_COMM_PRICE_SELECTION", t0."C_COMM_TIMECHUNK_STRING", t0."C_CREATION_DATE", t0."C_CREATOR_ID", t0."C_CURRENT_PRICE", t0."DC_DALSI_OPRAVNENI_1000009", t0."DC_DALSI_POVINNOSTI_1000009", t0."DC_DATUMTEST_1000002", t0."C_DECIMAL_PLACES", t0."DC_DODACI_1000037", t0."DC_DODAVKY_CTVRTLETI_1000015", t0."DC_DREVINA_1000037", t0."DC_DVOULETONT_1000026", t0."DC_DVOULETOVT_1000026", t0."DC_DVOUNT_1000026", t0."DC_DVOUPLATNOSTNT_1000026", t0."DC_DVOUPLATNOSTVT_1000026", t0."DC_DVOUVT_1000026", t0."DC_DVOUZIMANT_1000026", t0."DC_DVOUZIMAVT_1000026", t0."C_DF_CONTENT_DATA", t0."DC_EMAILTEST_1000002", t0."C_END_SHIFTED_FROM", t0."C_END_SHIFTED_TO", t0."DC_FORMA_1000009", t0."DC_FORMA_DOKLADU_1000009", t0."DC_FORMA_ZALOH_FAKTUR_1000009", t0."DC_HLMLLINK_1000002", t0."C_INDIVIDUAL_PRICE", t0."DC_JAKOSTKVALITA_1000037", t0."DC_JAKOSTNITRIDA_1000037", t0."DC_JEDN_CENY_1000009", t0."DC_JEDNOLETO_1000026", t0."DC_JEDNOTLIVA_1000009", t0."DC_JEDNOZIMA_1000026", t0."DC_KAPACITNI_1000015", t0."DC_KAPACITNI2_1000015", t0."C_LAST_VALID_PO_ID", t0."DC_LETO_1000026", t0."DC_LETONT_1000026", t0."DC_LETOST_1000026", t0."DC_LETOVK_1000026", t0."DC_LETOVT_1000026", t0."DC_LISTING_1000009", t0."DC_MALOVELKO_1000015", t0."C_MARKET_ID", t0."C_MAX_AUCTION_DURATIO
N_MINUTES", t0."C_MAX_PRICE", t0."C_MAX_PRICE_DIFF", t0."C_MIN_AMOUNT_OFFER", t0."C_MIN_PRICE", t0."C_MIN_PRICE_DIFF", t0."DC_MISTO_1000037", t0."C_MORE_OFFERS_ALLOWED", t0."DC_NADMEREK_1000037", t0."DC_NAPOJENI_PL_1000015", t0."C_NEXT_PRICE_STEP_DATE", t0."DC_ODBERNA_MISTA_1000009", t0."C_OFFER_CAN_EQUAL_ORIGINAL", t0."C_OFFER_STEP", t0."C_ORIGINAL_AMOUNT", t0."C_ORIGINAL_PRICE", t0."DC_OSTATNI_1000037", t0."DC_OSTATNI_PODMINKY_1000009", t0."DC_OSTATNIPODMINKY_1000007", t0."C_OWNER_END_FACTOR", t0."DC_PLATEBNI1_1000037", t0."DC_PLATEBNI2_1000037", t0."DC_PLATEBNI3_1000037", t0."DC_PLATEBNIPODMINKY_1000007", t0."DC_PODEPISUJE_1000009", t0."DC_PODEPISUJEV_1000009", t0."DC_POPIS_1000037", t0."DC_POPISKOMODITY_1000007", t0."C_PRESENTATION_TIMEOUT_MINUTES", t0."C_PRESUMED_AUCTION_DURATION_MINUTES", t0."C_PREV_PRICE_STEP_DATE", t0."C_PRICE_UNIT", t0."DC_PRILOHA_1000009", t0."DC_PRILOHA2_1000009", t0."C_PT_ID", t0."C_RECORD_FORM_VIEW_IDENTIFIER", t0."C_RECORD_FORM_PROTOTYPE_ID", t0."DC_REDUKCNI_1000037", t0."DC_ROK1_1000009", t0."DC_ROKNT_1000026", t0."DC_ROKST_1000026", t0."DC_ROKVK_1000026", t0."DC_ROKVT_1000026", t0."DC_ROZMERY_1000037", t0."DC_SAMOODECET_1000009", t0."DC_SAMOODECET3112_1000009", t0."DC_SAMOODECETDATUM_1000009", t0."DC_SANKCE_1000015", t0."DC_SANKCE2_1000015", t0."C_AUCTION_END_DATE", t0."C_QUEUED_AUCTION_DID_START_DATE", t0."C_PRESENTATION_END_DATE", t0."DC_SJEDNAVANI_DIAGRAMU_1000009", t0."DC_SKUTECNOSTI_1000037", t0."DC_SML_KONTAKT_AUKCE_1000009", t0."DC_SOUPIS_PRILOH_1000009", t0."DC_SPLATNEKDNI_1000009", t0."DC_SPLATNOST_1000009", t0."DC_SUBORG_1000009", t0."DC_SUJ_1000037", t0."DC_SWITCHTEST_1000002", t0."DC_TABLE_1000002", t0."DC_TABULKA_1000037", t0."DC_TABULKA_TARIFU_NN_1000009", t0."DC_TABULKATEXT_1000037", t0."DC_TERMIN_1000037", t0."DC_TERMIN_DO_1000009", t0."DC_TERMIN_OD_1000009", t0."C_TIME_SHIFT_INTERVAL", t0."C_TIME_CHUNK_UID", t0."C_TITLE", t0."DC_TLOUSTKOVYSTUPEN_1000037", t0."DC_TLOUSTKY_1000037", t0."DC_TOLERANCE_1000015", t0."DC_TOLERANCE2_1000015", t0."DC_TRIPLATNOSTNT_1000026"
, t0."DC_TRIPLATNOSTST_1000026", t0."DC_TRIPLATNOSTVK_1000026", t0."DC_TRIPLATNOSTVT_1000026", t0."DC_TYP_MERENI_1000015", t0."DC_TYPEOFWOODDRUHDREVA_1000002", t0."C_UID", t0."C_UNDERBELLY_RS_IDENTIFIER", t0."C_UNITED_RS_IDENTIFIER", t0."DC_URLOBRAZEK_1000002", t0."DC_URLTEST_1000002", t0."DC_VN_PO_MESICICH_1000009", t0."DC_WOODTYPE_1000002", t0."DC_YOUTUBEVIDEO_1000002", t0."DC_ZIMA_1000026", t0."DC_ZIMANT_1000026", t0."DC_ZIMAST_1000026", t0."DC_ZIMAVK_1000026", t0."DC_ZIMAVT_1000026", t0."DC_ZPRAVA_1000009", t0."DC_ZUCTOVACI_1000009" FROM "T_AUCTION" t0 WHERE t0."C_UID" = 1000762 //log:er.extensions.ERXAdaptorChannelDelegate.sqlLogging [WorkerThread13]
> ===
>
>
> _______________________________________________
> 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