[Info-ingres] Weird problem in Ingres 10

Thu May 17 15:18:31 UTC 2018

On Thu, 17 May 2018 15:03:18 +0000, Alex Hanshaw
<Alex.Hanshaw at actian.com> wrote:

>One of my guys recently added the ability to dump audit data to a trl file with a timestamp rather than an Ingres date as the first column so that millisecond precision is included.
>Part of the test plan he developed included abort and abort to savepoint and the records are included if you use the right flag on auditdb. E.g.
>auditdb -table=b133019 -aborted_transactions -file=b133019.trl -timestamp b133019db
>Omit the -timestamp option if you don't have a patch with that functionality. There's a section in the docs that lets you create a table to load the trl file and then you can see the audit records.

I have run this command and get a binary file as output.  How can I
interpret this file?

>Alex
>
>From: Laframboise, André (BAC/LAC) <andre.laframboise at canada.ca>
>Sent: 17 May 2018 15:37
>To: Alex Hanshaw <Alex.Hanshaw at actian.com>; Martin Bowes <martin.bowes at ndph.ox.ac.uk>; info-ingres at lists.planetingres.org
>Subject: RE: [Info-ingres] Weird problem in Ingres 10
>
>Are you sure ?  Even Log full aborts that rolls back thousands of rows ?
>
>André Laframboise
>
>Conseiller Principal Base de Données, Direction générale de l'Innovation et du Dirigeant principal de l'information
>Bibliothèque et Archives Canada<http://www.bac-lac.gc.ca/fra/Pages/bac-web.aspx> / Gouvernement du Canada
>andre.laframboise at canada.ca<mailto:andre.laframboise at canada.ca> / Tél. : 613-298-1346
>
>Senior Database Advisor, Innovation and Chief Information Officer Branch
>Library and Archives Canada<http://www.bac-lac.gc.ca/eng/Pages/lac-web.aspx> / Government of Canada
>andre.laframboise at canada.ca<mailto:andre.laframboise at canada.ca> / Tel: 613-298-1346
>
>[http://www.bac-lac.gc.ca/eng/events/PublishingImages/banner.jpg]<http://www.bac-lac.gc.ca/eng/events/Pages/events.aspx>
>
>From: info-ingres-bounces at lists.planetingres.org<mailto:info-ingres-bounces at lists.planetingres.org> <info-ingres-bounces at lists.planetingres.org<mailto:info-ingres-bounces at lists.planetingres.org>> On Behalf Of Alex Hanshaw
>Sent: Thursday, May 17, 2018 10:32 AM
>To: Martin Bowes <martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>>; info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>
>aborted statements should also appear in auditdb output.
>
>From: info-ingres-bounces at lists.planetingres.org<mailto:info-ingres-bounces at lists.planetingres.org> <info-ingres-bounces at lists.planetingres.org<mailto:info-ingres-bounces at lists.planetingres.org>> On Behalf Of Martin Bowes
>Sent: 17 May 2018 15:00
>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>
>Please remove it. You may get a swathe of data but in this case more may shed some light on the issue.
>
>Are there any other processes you know of which are monkeying with the data?
>
>Is there a good reason why there is nojournaling on this table? Can we turn it on ... which will entail backing up the database as well.
>
>Marty
>
>-----Original Message-----
>From: Mark [mailto:i at dontgetlotsofspamanymore.net]
>Sent: 17 May 2018 14:54
>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>
>On Thu, 17 May 2018 13:43:35 +0000, Martin Bowes
><martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>> wrote:
>
>>Hi Mark,
>>
>>I note that you are turning off the sc930 trace with a SET TRACE POINT SC930 0 which is still presumably in your ESQLC script. Sadly I think that is masking what is happening here as on the first occasion we lost nearly two minutes of activity, then over a minute on the second and over 4minutes on the third occasion. Could you
please remove that from the script and try again.
>
>I wanted to disable the tracing after the problematic statement had
>finished. I can remove this if there may be useful data shown
>otherwise.
>
>>If this table is journaled could you please also check with auditdb for an insert of the message_id = ' 100055700000XDBW' record after 10:34:06
>
>The table is not journalled.
>
>>Marty
>>
>>-----Original Message-----
>>From: Martin Bowes [mailto:martin.bowes at ndph.ox.ac.uk]
>>Sent: 17 May 2018 14:31
>>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>
>>Whoops sorry, I'll take that back there are 4 queries.
>>
>>The first and the fourth queries are seemingly identical and the fourth indicates a rowcount 1 on the update.
>>
>>I'll have a closer look.
>>
>>Marty
>>
>>-----Original Message-----
>>From: Martin Bowes [mailto:martin.bowes at ndph.ox.ac.uk]
>>Sent: 17 May 2018 14:25
>>To: Mark; info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>
>>Hi Mark,
>>
>>That trace shows three successive update attempts each with a different message_id. The first one updates no rows the others update a single row.
>>
>>So can you do a:
>>select count(*) from db_msg where message_id = ' 100055700000XDBW' and queue <> ' log_20150325' /* rowcount = 0 */
>>
>>select count(*) from db_msg where message_id = ' 400055700000XDBW' and queue <> ' log_20150325' /* rowcount = 1 */
>>
>>select count(*) from db_msg where message_id = ' 500055700000XDBW' and queue <> ' log_20150325' /* rowcount = 1 */
>>
>>Marty
>>
>>-----Original Message-----
>>From: Mark [mailto:i at dontgetlotsofspamanymore.net]
>>Sent: 17 May 2018 14:17
>>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>
>>On Thu, 17 May 2018 13:03:16 +0000, Martin Bowes
>><martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>> wrote:
>>
>>>Sorry, my bad that should have been a line starting: SESSION BEGINS
>>>
>>>Can you send the update queries and parameters (if any) from the good and bad cases. Those won't show any private data, so it should be cool.
>>
>>Cheers. I have emailed you the logs.
>>
>>>Marty
>>>
>>>-----Original Message-----
>>>From: Mark [mailto:i at dontgetlotsofspamanymore.net]
>>>Sent: 17 May 2018 13:51
>>>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>>
>>>On Thu, 17 May 2018 12:35:38 +0000, Martin Bowes
>>><martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>> wrote:
>>>
>>>>Going out on a limb here...
>>>>
>>>>Are we sure the two sessions are working on the same table owned by the same user in the same database as each other?
>>>
>>>I am only using a single session for this.
>>>
>>>>In the sc930 trace file can you find the connection information immediately prior to the update code. You are looking for a line like:
>>>>BEG 27/03/2018 13:26:07.598545, Database: iidbdb, User: ingres
>>>
>>>There's nothing like this in the trace files.
>>>
>>>>You could also check your database and see if there are any duplicates of the table with the query:
>>>>Select table_owner from iitables where table_name='YOURTABLE';
>>>>
>>>>Do that for each table involved in the update.
>>>
>>>Only 1 row (& only 1 table in the update).
>>>
>>>>Marty
>>>>
>>>>-----Original Message-----
>>>>From: Mark [mailto:i at dontgetlotsofspamanymore.net]
>>>>Sent: 17 May 2018 13:21
>>>>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>>>
>>>>On Thu, 17 May 2018 12:06:48 +0000, Martin Bowes
>>>><martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>> wrote:
>>>>
>>>>>No error code and with a rowcount of zero means the update is successful, but had no work to do.
>>>>>
>>>>>I presume there is a where clause in the update and that it looks OK.
>>>>
>>>>There is a where clause and it does match a record so there is "work
>>>>to do".
>>>>
>>>>>Can you compare the code which worked and the code which didn't work for discrepancies?
>>>>
>>>>Yes. They are exactly the same! And it only fails the first time it
>>>>is executed, all other times work fine.
>>>>
>>>>>Marty
>>>>>
>>>>>-----Original Message-----
>>>>>From: Mark [mailto:i at dontgetlotsofspamanymore.net]
>>>>>Sent: 17 May 2018 12:57
>>>>>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>>>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>>>>
>>>>>On Thu, 17 May 2018 11:21:37 +0000, Martin Bowes
>>>>><martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>> wrote:
>>>>>
>>>>>>Twice...
>>>>>>
>>>>>>Once where it updates the data and once where it puts it back the way it was?
>>>>>
>>>>>No. The data is the same for each.
>>>>>
>>>>>>What do the Rowcount figures say on each statement?
>>>>>
>>>>>0.
>>>>>
>>>>>>Marty
>>>>>>
>>>>>>-----Original Message-----
>>>>>>From: Mark [mailto:i at dontgetlotsofspamanymore.net]
>>>>>>Sent: 17 May 2018 12:12
>>>>>>To: info-ingres at lists.planetingres.org<mailto:info-ingres at lists.planetingres.org>
>>>>>>Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>>>>>
>>>>>>On Wed, 16 May 2018 12:40:48 -0400, Karl and Betty Schendel
>>>>>><schendel at kbcomputer.com<mailto:schendel at kbcomputer.com>> wrote:
>>>>>>
>>>>>>>SC930 tracing is server wide and runs until you stop it with set notrace sc930.
>>>>>>>So you can connect to any database, do the set trace record '/some/ingres-writable/dir'
>>>>>>>and the set trace point sc930, go to the trace record directory you gave it and
>>>>>>>ensure that there's at least something there (should be one or more sessNNNNN files),
>>>>>>>and then you can run your esql program until the fault happens.
>>>>>>>
>>>>>>>You don't actually need to put the sc930 into the esql program unless you want to
>>>>>>>do it that way.
>>>>>>>
>>>>>>>Once you capture what you need to capture, set notrace point sc930 turns it off.
>>>>>>>
>>>>>>>You'll need the trace point privilege, simplest is to do it as the installation owner
>>>>>>>(user ingres, traditionally).
>>>>>>
>>>>>>Thanks again. We now have traces but they don't help me. The traces
>>>>>>include the SQL statement and the data but, pretty much, nothing else.
>>>>>>
>>>>>>The only notable thing I observed is that the data is traced twice for
>>>>>>the failed transaction and only once for the successful ones.
>>>>>>
>>>>>>There are no error messages.
>>>>>>
>>>>>>>Karl
>>>>>>>
>>>>>>>> On May 16, 2018, at 11:12 AM, Mark <i at dontgetlotsofspamanymore.net<mailto:i at dontgetlotsofspamanymore.net>> wrote:
>>>>>>>>
>>>>>>>> On Wed, 16 May 2018 12:11:08 +0000, Martin Bowes
>>>>>>>> <martin.bowes at ndph.ox.ac.uk<mailto:martin.bowes at ndph.ox.ac.uk>> wrote:
>>>>>>>>
>>>>>>>>> Just to expand on Karl's sc930...You may already know this...
>>>>>>>>>
>>>>>>>>> To turn it on, make a recording directory...mkdir /full/path/to/directory'
>>>>>>>>>
>>>>>>>>> And then...
>>>>>>>>> sql iidbdb << SQL_END
>>>>>>>>> set trace record '/full/path/to/directory';
>>>>>>>>> set trace point sc930 1;
>>>>>>>>> \p\g
>>>>>>>>> \q
>>>>>>>>> SQL_END
>>>>>>>>
>>>>>>>> Do I need to run this on the server account? I have implemented it
>>>>>>>> currently in the embedded SQL of my program.
>>>>>>>>
>>>>>>>>> FYI. The digit after the sc930 indicates a tracing level, 1 should be sufficient.
>>>>>>>>>
>>>>>>>>> Run the errant query.
>>>>>>>>>
>>>>>>>>> And turn off the sc930.
>>>>>>>>> sql iidbdb << SQL_END
>>>>>>>>> set trace point sc930 0;
>>>>>>>>> \p\g
>>>>>>>>> \q
>>>>>>>>> SQL_END
>>>>>>>>>
>>>>>>>>> You can now access the recording directory and start scanning the files for any sign of life from your query.
>>>>>>>>>
>>>>>>>>> Marty
>>>>>>>>>
>>>>>>>>> -----Original Message-----
>>>>>>>>> From: Karl and Betty Schendel [mailto:schendel at kbcomputer.com]
>>>>>>>>> Sent: 16 May 2018 12:54
>>>>>>>>> To: Ingres and related product discussion forum
>>>>>>>>> Subject: Re: [Info-ingres] Weird problem in Ingres 10
>>>>>>>>>
>>>>>>>>> On May 16, 2018, at 7:44 AM, Mark <i at dontgetlotsofspamanymore.net<mailto:i at dontgetlotsofspamanymore.net>> wrote:
>>>>>>>>>>
>>>>>>>>>> On Tue, 15 May 2018 12:27:09 -0400, Karl and Betty Schendel
>>>>>>>>>> <schendel at kbcomputer.com<mailto:schendel at kbcomputer.com>> wrote:
>>>>>>>>>>
>>>>>>>>>>> It's certainly not something I have heard of or seen before. Do you have any rules
>>>>>>>>>>> defined on the relevant tables? Try enabling LOG_TRACE if the problem is
>>>>>>>>>>> sufficiently predictable, or do a logdump after the problem occurs if it's not;
>>>>>>>>>>> the idea being to try to see whether you actually got any PUT (insert) or
>>>>>>>>>>> REP (replace) log records that were then rolled back, or whether the insert / update
>>>>>>>>>>> was never executed at all.
>>>>>>>>>>
>>>>>>>>>> After enabling log_trace all I got was:
>>>>>>>>>>
>>>>>>>>>> LOG: SAVEPOINT Size written/reserved: 0/ 0 Flags:
>>>>>>>>>> -------------------------------------------------------------------
>>>>>>>>>
>>>>>>>>> So the insert/update isn't ever being executed. Either it's failing with some sort of
>>>>>>>>> silent error, which would seem odd, or it's not reaching the backend at all, or
>>>>>>>>> it's being pre-empted by a before rule. I think the next step would be to enable
>>>>>>>>> sc930 tracing and see if the backend is getting the insert-update, and what
>>>>>>>>> end-of-query status it's recording. There should be KB articles on enabling
>>>>>>>>> SC930 tracing.
>>>>>>>>>
>>>>>>>>> Karl
>>>>>>>>>
>>>>>>>>> _______________________________________________
>>>>>>>>> Info-ingres mailing list
>>>>>>>>> Info-ingres at lists.planetingres.org<mailto:Info-ingres at lists.planetingres.org>
>>>>>>>>> http://lists.planetingres.org/mailman/listinfo/info-ingres<http://lists.planetingres.org/mailman/listinfo/info-ingres>
>>>>>>>>
>>>>>>>> --
>>>>>>>> <insert witty sig here>
>>>>>>>> _______________________________________________
>>>>>>>> Info-ingres mailing list
>>>>>>>> Info-ingres at lists.planetingres.org<mailto:Info-ingres at lists.planetingres.org>
>>>>>>>> http://lists.planetingres.org/mailman/listinfo/info-ingres<http://lists.planetingres.org/mailman/listinfo/info-ingres>

-- 
<insert witty sig here>