Logical Log backup during L1 archive
On IDS 9.30 on HP-UX with onbar/ISM backing up to disk, logical logs that filled during a level-0 whole-system archive were normally backed up immediately, but one night five logs sat unbacked-up for about four hours, with the ALARMPROGRAM script logging "Logical log backup already running" and no errors elsewhere. Jason Harris explained it as expected ISM behaviour: after the log backup, ISM's index/bootstrap save ran to the same ISMDiskLogs pool, which accepts only one job at a time, so log backup requests during that window were refused and not retried until the next log filled. Suggested fixes: have the warning script re-issue onbar -b -l, and/or direct the index backup to the ISMDiskData pool.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
Morning all
An odd one which I have a faint bell ringing at the back of my head about...
IDS9.30HC5, HP-UX11i
We run our L1 backups using onbar -L0 -w via ISM to disk, for dbspaces and for logical logs. This is usually started at around 8.30 pm when all the users have been logged off the system and lasts for 6hrs or so; during this slack time we also run our housekeeping and dba tidyups etc. Quite consistently (as evidenced by runtime logs), at around 10.20 pm and while the L1 is well under way, one of the dba tidyups is deleting some old simple blobs (some byte data) and uses 4 or 5 logical logs in quick succession; these are usually the only logical logs that fill while the L1 is running.
Every night when this happens, the logs are backed up immediately - we see
22:16:02 Logical Log 366458 Complete.
22:16:02 Logical Log 366458 - Backup Started
22:16:05 Logical Log 366458 - Backup Completedin the online log for each of them.
Last night, we got only the "Complete" message at the usual time but they didn't start backing up until 02:15 or so when the L1 still had a couple of dbspaces to go. There's nothing in the online log or bar_act.log showing any problems, no untoward syslog.log "waiting for media"-type messages, and the L1 was quite happily backing up dbspaces all the while.
I've got something nagging in my mind from way back about backing up logical logs during the L1 but I'm damned if I can remember what it is...
Anyone?
Sorry, to clarify, logical logs are backed up continuously using a script called by ALARMPROGRAM. Oh hang on..the output from our ALARMPROGRAM script says "Logical log backup already running" for the period in question, once for each of the 5 logs filled. Hmmm
Good grief you can tell it's Friday. Level 0, not Level 1. It's my age...
I'm coming up blank.
Art
Art S. Kagel
Advanced DataTools (www.advancedatatools.com)
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions
and do not reflect on my employer, Advanced DataTools, the IIUG, nor any
other organization with which I am associated either explicitly,
implicitly, or by inference. Neither do those opinions reflect those of
other individuals affiliated with any entity with which I am affiliated nor
those of the entities themselves.
On Fri, Apr 27, 2012 at 1:32 AM, Malc P <malcrp@googlemail.com> wrote:
> Morning all
> An odd one which I have a faint bell ringing at the back of my head
> about...
> IDS9.30HC5, HP-UX11i
> We run our L1 backups using onbar -L0 -w via ISM to disk, for dbspaces and
> for logical logs. This is usually started at around 8.30 pm when all the
> users have been logged off the system and lasts for 6hrs or so; during this
> slack time we also run our housekeeping and dba tidyups etc. Quite
> consistently (as evidenced by runtime logs), at around 10.20 pm and while
> the L1 is well under way, one of the dba tidyups is deleting some old
> simple blobs (some byte data) and uses 4 or 5 logical logs in quick
> succession; these are usually the only logical logs that fill while the L1
> is running.
> Every night when this happens, the logs are backed up immediately - we see
> 22:16:02 Logical Log 366458 Complete.
> 22:16:02 Logical Log 366458 - Backup Started
> 22:16:05 Logical Log 366458 - Backup Completed> in the online log for each of them.
> Last night, we got only the "Complete" message at the usual time but they
> didn't start backing up until 02:15 or so when the L1 still had a couple of
> dbspaces to go. There's nothing in the online log or bar_act.log showing
> any problems, no untoward syslog.log "waiting for media"-type messages, and
> the L1 was quite happily backing up dbspaces all the while.
> I've got something nagging in my mind from way back about backing up
> logical logs during the L1 but I'm damned if I can remember what it is...
> Anyone?
> _______________________________________________
> Informix-list mailing list
> Informix-list@iiug.org
> http://www.iiug.org/mailman/listinfo/informix-list
>
Hello Malc,
Looooonnnggggg shot.... may be way off here...
ism has 4 streams max as paralelization and one can configure it how
many are available
and how many per device etc.
if all of them are used with the L0 then the LL backup has to wait
until a stream in ism
is available..
Superboer.
On 27 apr, 13:35, Art Kagel <art.ka...@gmail.com> wrote:
> I'm coming up blank.
>
> Art
>
> Art S. Kagel
> Advanced DataTools (www.advancedatatools.com)
> Blog:http://informix-myview.blogspot.com/
>
> Disclaimer: Please keep in mind that my own opinions are my own opinions
> and do not reflect on my employer, Advanced DataTools, the IIUG, nor any
> other organization with which I am associated either explicitly,
> implicitly, or by inference. Neither do those opinions reflect those of
> other individuals affiliated with any entity with which I am affiliated nor
> those of the entities themselves.
>
> On Fri, Apr 27, 2012 at 1:32 AM, Malc P <mal...@googlemail.com> wrote:
> > Morning all
> > An odd one which I have a faint bell ringing at the back of my head
> > about...
> > IDS9.30HC5, HP-UX11i
> > We run our L1 backups using onbar -L0 -w via ISM to disk, for dbspaces and
> > for logical logs. This is usually started at around 8.30 pm when all the
> > users have been logged off the system and lasts for 6hrs or so; during this
> > slack time we also run our housekeeping and dba tidyups etc. Quite
> > consistently (as evidenced by runtime logs), at around 10.20 pm and while
> > the L1 is well under way, one of the dba tidyups is deleting some old
> > simple blobs (some byte data) and uses 4 or 5 logical logs in quick
> > succession; these are usually the only logical logs that fill while the L1
> > is running.
> > Every night when this happens, the logs are backed up immediately - we see
> > 22:16:02 Logical Log 366458 Complete.
> > 22:16:02 Logical Log 366458 - Backup Started
> > 22:16:05 Logical Log 366458 - Backup Completed> > in the online log for each of them.
> > Last night, we got only the "Complete" message at the usual time but they
> > didn't start backing up until 02:15 or so when the L1 still had a couple of
> > dbspaces to go. There's nothing in the online log or bar_act.log showing
> > any problems, no untoward syslog.log "waiting for media"-type messages, and
> > the L1 was quite happily backing up dbspaces all the while.
> > I've got something nagging in my mind from way back about backing up
> > logical logs during the L1 but I'm damned if I can remember what it is...
> > Anyone?
> > _______________________________________________
> > Informix-list mailing list
> > Informix-l...@iiug.org
> >http://www.iiug.org/mailman/listinfo/informix-list
On Friday, 27 April 2012 18:57:12 UTC+1, Superboer wrote:
> Hello Malc,
>
> Looooonnnggggg shot.... may be way off here...
>
>
> ism has 4 streams max as paralelization and one can configure it how
> many are available
> and how many per device etc.
>
> if all of them are used with the L0 then the LL backup has to wait
> until a stream in ism
> is available..
OK... ism_show -config is showing "parallelism 4". We're backing up whole-system, so that should only be 1 thread at a time (sequential dbspaces).
Going back through the online log, I get the following for the log logs in question:
22:16:02 Logical Log 366458 - Backup Started
22:16:05 Logical Log 366458 - Backup Completed
22:16:09 Logical Log 366459 Complete.
22:16:14 Logical Log 366460 Complete.
22:16:18 Logical Log 366461 Complete.
22:16:21 Logical Log 366462 Complete.
02:11:21 Logical Log 366463 Complete.
02:11:22 Logical Log 366459 - Backup Started
02:11:26 Logical Log 366459 - Backup Completed
02:11:26 Logical Log 366460 - Backup Started
02:11:28 Logical Log 366460 - Backup Completed
02:11:28 Logical Log 366461 - Backup Started
02:11:31 Logical Log 366461 - Backup Completed
02:11:31 Logical Log 366462 - Backup Started
02:11:33 Logical Log 366462 - Backup Completed
02:11:33 Logical Log 366463 - Backup Started
02:11:35 Logical Log 366463 - Backup Completed...so after log 366458 completed and was backed up, 5 more logs filled and weren't backed up until 4 hours later.
bar_act.log shows:
2012-04-25 22:16:02 386 374 Begin backup logical log 366458.
2012-04-25 22:16:05 386 374 Completed backup logical log 366458 (Storage Manag
er copy ID: 128345 0).
2012-04-26 02:11:22 23591 23573 Begin backup logical log 366459.
2012-04-26 02:11:26 23591 23573 Completed backup logical log 366459 (Storage M
anager copy ID: 128452 0).
... and so on for the rest of those logs.
ism/logs/daemon.log has:
04/25/12 22:16:03 nsrd: live.enterprise.capita.zone:INFORMIX:/robinshm/0/366458
saving to pool 'ISMDiskLogs' (LOGLOGS)
04/25/12 22:16:05 nsrd: live.enterprise.capita.zone:INFORMIX:/robinshm/0/366458
done saving to pool 'ISMDiskLogs' (LOGLOGS) 11 MB
04/25/12 22:16:08 nsrd: savegroup info: starting ISMDiskLogs (with 1 client(s))
04/25/12 22:16:09 nsrd: live.enterprise.capita.zone:/opt/informix_9.3/ism/index/
live.enterprise.capita.zone saving to pool 'ISMDiskLogs' (LOGLOGS)
04/25/12 22:16:10 nsrd: live.enterprise.capita.zone:/opt/informix_9.3/ism/index/
live.enterprise.capita.zone done saving to pool 'ISMDiskLogs' (LOGLOGS) 1.1 MB
04/25/12 22:16:10 nsrd: live.enterprise.capita.zone:bootstrap saving to pool 'IS
MDiskLogs' (LOGLOGS)
04/25/12 22:16:14 nsrd: live.enterprise.capita.zone:bootstrap done saving to poo
l 'ISMDiskLogs' (LOGLOGS) 3.4 MB
04/25/12 22:16:10 nsrd: live.enterprise.capita.zone:/opt/informix_9.3/ism/index/
live.enterprise.capita.zone done saving to pool 'ISMDiskLogs' (LOGLOGS) 1.1 MB
04/25/12 22:16:10 nsrd: live.enterprise.capita.zone:bootstrap saving to pool 'IS
MDiskLogs' (LOGLOGS)
04/25/12 22:16:14 nsrd: live.enterprise.capita.zone:bootstrap done saving to poo
l 'ISMDiskLogs' (LOGLOGS) 3.4 MB
04/25/12 22:16:22 nsrd: savegroup notice: ISMDiskLogs completed, 1 client(s) (Al
l Succeeded)
...and then several dbspaces under the L0 until:
04/26/12 02:11:23 nsrd: live.enterprise.capita.zone:INFORMIX:/robinshm/0/366459
saving to pool 'ISMDiskLogs' (LOGLOGS)
04/26/12 02:11:25 nsrd: live.enterprise.capita.zone:INFORMIX:/robinshm/0/366459
done saving to pool 'ISMDiskLogs' (LOGLOGS) 10 MB
Hmmm. Looks like ISM wasn't even called until 02:16 after log 366458 was backed up. I can't see anything else that gives any clues; I can't find any similar delays going back a year in our log files so it may be just "one of those things". Problem is, management don't accept "one of those things" as a reason for an error report so I think I'll just have to improve monitoring in case it happens again to record process activity...
Hi Malc, This is the expected behavior of ISM. During the period of time from 22:16:09 - 22:16:21, when the logical logs completed, a backup cannot be started. This is because you are also running an index/boot strap backup to the ISMDiskLogs pool. The ISMDiskLogs pool cam only accept one backup at a time, This line shows the index backup starting: 04/25/12 22:16:09 nsrd: live.enterprise.capita.zone:/opt/informix_9.3/ ism/index/live.enterprise.capita.zone saving to pool 'ISMDiskLogs' (LOGLOGS) This line shows the index backup competing: 04/25/12 22:16:22 nsrd: savegroup notice: ISMDiskLogs completed, 1 client(s) (All Succeeded) This is why the message "logical log backup is already running" appears in your ALARMPROGRAM log file. When the next logical log filled at 02:21:22, that backup was able to start, and it backed up all outstanding logical logs. If the next logical log had completed any time after 22:16:22, when the index backup was complete, the backups would have run then. Cheers, Jason
On Monday, 30 April 2012 13:26:00 UTC+1, Jason Harris wrote:
> Hi Malc,
>
> This is the expected behavior of ISM.
...[snip]...
Aha! Jason, thanks, I think I can see that - a log fills, so ISM backs that up followed by the nsr internal indexes and the bootstrap (hence the initial report of 11Mb for the logical log plus the subsequent 1.1Mb and 3.4Mb reports). And a log filling only issues the one request to ISM, but ISM's busy at the time and says go away...
Maybe I'll make a small mod in our unbacked-up log warning script to issue an onbar -b -l again as long as the log backup script is idle and only issuing a warning if this doesn't work.
Brilliant response, I love this group!
> Aha! Jason, thanks, I think I can see that - a log fills, so ISM backs that up followed by the nsr internal indexes and the bootstrap (hence the initial report of 11Mb for the logical log plus the subsequent 1.1Mb and 3.4Mb reports). And a log filling only issues the one request to ISM, but ISM's busy at the time and says go away...
Yes!
> Maybe I'll make a small mod in our unbacked-up log warning script to issue an onbar -b -l again as long as the log backup script is idle and only issuing a warning if this doesn't work.
That would catch it.
While you should always be careful changing backup and restore procedures, and with disclaimers set to the max, you might consider directing the index backup to the ISMDiskData pool instead. The index and dbspace backups should wait for each other in this pool, leaving the logical logs free to backup anytime.