Strange HDR behaviour
Posted in 2013
On IDS 12.10.FC1 / Solaris 11 SPARC, after setting up HDR with a physical restore, the secondary reported "HDR secondary server operational", but every restart of the secondary (shut down with onmode -ky) made the primary resend logical logs starting from an old log (1411) while the current log was 1500+, taking about an hour to catch up. Responders asked about onstat -g dri sync status and shutdown method, suggested nothing was being checkpointed/written to disk on the secondary, and raised a known "SMX thread is exiting"/dropped-connectivity issue to look for in the message logs. No resolution is recorded in the thread.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
Topics: High Availability & Replication, Logging & Checkpoints, Platform-Specific Issues
We are using IDS 12.10.FC1 and Solaris 11.1 Sparc and experience a strange behaviour with HDR. After i started HDR by performing a physical restore onto the secondary server i got the message "DR: HDR secondary server operational" which means that everything is ok. Now, everytime i restart the instance on the secondary server it starts to transfer all logical logs from primary to secondary. Today the primary server had log number 1501 as current log. The primary start to transfer logs from 1411 which is many days back in time. After an hour or so everything is up to date and i get "DR: HDR secondary server operational" in the online.log file. Anyone who have seen this behaviour before and can give me a hint that can solve the problem ? Regards Plexor
Can you keep track of the servers' sync status day-to-day using onstat -g
dri? Are they remaining in sync between restarts? How to you shutdown the
secondary?
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, Jul 19, 2013 at 6:38 AM, <> wrote:
> We are using IDS 12.10.FC1 and Solaris 11.1 Sparc and experience a strange
> behaviour with HDR. After i started HDR by performing a physical restore
> onto
> the secondary server i got the message "DR: HDR secondary server
> operational"
> which means that everything is ok.
>
> Now, everytime i restart the instance on the secondary server it starts to
> transfer all logical logs from primary to secondary. Today the primary
> server
> had log number 1501 as current log. The primary start to transfer logs from
> 1411 which is many days back in time. After an hour or so everything is up
> to
> date and i get "DR: HDR secondary server operational" in the online.log
> file.
>
> Anyone who have seen this behaviour before and can give me a hint that can
> solve the problem ?
>
> Regards
> Plexor
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--001a1133e414682dc304e1dafe16
I am using 'onmode -ky' to shut it down.
I restarted the secondary server this morning and it starts to transfer
logical logs again from number 1411. Current log at the primary is 1575.
Here is the log from the primary:
05:05:51 DR: Primary server connected
05:05:51 DR: Using default behavior of failure-recovering Secondary server
05:05:52 DR: Sending log 1411, size 128000 pages, 100.00 percent used
05:06:56 DR: Sending log 1412, size 128000 pages, 100.00 percent used
05:07:59 DR: Sending log 1413, size 128000 pages, 100.00 percent used
05:09:04 DR: Sending log 1414, size 128000 pages, 100.00 percent used
.. and here is the log from the secondary:
05:04:08 Recovery Mode
05:04:10 DR: Secondary server connected
05:04:11 DR: Using default behavior of failure-recovering Secondary server
05:04:12 DR: Failure recovery from disk in progress ...
05:04:12 Logical Recovery Started.
05:04:12 96 recovery worker threads will be started.
05:04:12 Start Logical Recovery - Start Log 1411, End Log ?
05:04:12 Starting Log Position - 1575 0xf645650
05:05:17 Logical Log 1411 Complete, timestamp: 0xf1f41909.
05:06:21 Logical Log 1412 Complete, timestamp: 0xf1f41909.
05:07:24 Logical Log 1413 Complete, timestamp: 0xf1f41909.
05:08:29 Logical Log 1414 Complete, timestamp: 0xf1f41909.
05:09:33 Logical Log 1415 Complete, timestamp: 0xf1f41909.
I have no idea why it behaves like this ?
/Jimmy
'Jimmy'
Versions and platform would be useful.
Did you shut down primary or secondary, and why ?
When was this shut down, how long ago, how many logs ago ?
A few more lines (25 - 50) from the logs prior to this point would help.
Keith
On 22 July 2013 04:13, <> wrote:
> I am using 'onmode -ky' to shut it down.
>
> I restarted the secondary server this morning and it starts to transfer
> logical logs again from number 1411. Current log at the primary is 1575.
>
> Here is the log from the primary:
>
> 05:05:51 DR: Primary server connected
> 05:05:51 DR: Using default behavior of failure-recovering Secondary server
> 05:05:52 DR: Sending log 1411, size 128000 pages, 100.00 percent used
> 05:06:56 DR: Sending log 1412, size 128000 pages, 100.00 percent used
> 05:07:59 DR: Sending log 1413, size 128000 pages, 100.00 percent used
> 05:09:04 DR: Sending log 1414, size 128000 pages, 100.00 percent used
>
> ... and here is the log from the secondary:
>
> 05:04:08 Recovery Mode
> 05:04:10 DR: Secondary server connected
> 05:04:11 DR: Using default behavior of failure-recovering Secondary server
> 05:04:12 DR: Failure recovery from disk in progress ...
> 05:04:12 Logical Recovery Started.
> 05:04:12 96 recovery worker threads will be started.
> 05:04:12 Start Logical Recovery - Start Log 1411, End Log ?
> 05:04:12 Starting Log Position - 1575 0xf645650
> 05:05:17 Logical Log 1411 Complete, timestamp: 0xf1f41909.
> 05:06:21 Logical Log 1412 Complete, timestamp: 0xf1f41909.
> 05:07:24 Logical Log 1413 Complete, timestamp: 0xf1f41909.
> 05:08:29 Logical Log 1414 Complete, timestamp: 0xf1f41909.
> 05:09:33 Logical Log 1415 Complete, timestamp: 0xf1f41909.
>
> I have no idea why it behaves like this ?
>
> /Jimmy
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--047d7b60518c0f8fa504e215c993
It sounds like nothing is ever written to disk on the secondary before it
is shutdown or killed, almost as if you were doing a restore of the
secondary withan archive taken at log # 1411 before starting it up.
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 Sun, Jul 21, 2013 at 11:13 PM, <> wrote:
> I am using 'onmode -ky' to shut it down.
>
> I restarted the secondary server this morning and it starts to transfer
> logical logs again from number 1411. Current log at the primary is 1575.
>
> Here is the log from the primary:
>
> 05:05:51 DR: Primary server connected
> 05:05:51 DR: Using default behavior of failure-recovering Secondary server
> 05:05:52 DR: Sending log 1411, size 128000 pages, 100.00 percent used
> 05:06:56 DR: Sending log 1412, size 128000 pages, 100.00 percent used
> 05:07:59 DR: Sending log 1413, size 128000 pages, 100.00 percent used
> 05:09:04 DR: Sending log 1414, size 128000 pages, 100.00 percent used
>
> ... and here is the log from the secondary:
>
> 05:04:08 Recovery Mode
> 05:04:10 DR: Secondary server connected
> 05:04:11 DR: Using default behavior of failure-recovering Secondary server
> 05:04:12 DR: Failure recovery from disk in progress ...
> 05:04:12 Logical Recovery Started.
> 05:04:12 96 recovery worker threads will be started.
> 05:04:12 Start Logical Recovery - Start Log 1411, End Log ?
> 05:04:12 Starting Log Position - 1575 0xf645650
> 05:05:17 Logical Log 1411 Complete, timestamp: 0xf1f41909.
> 05:06:21 Logical Log 1412 Complete, timestamp: 0xf1f41909.
> 05:07:24 Logical Log 1413 Complete, timestamp: 0xf1f41909.
> 05:08:29 Logical Log 1414 Complete, timestamp: 0xf1f41909.
> 05:09:33 Logical Log 1415 Complete, timestamp: 0xf1f41909.
>
> I have no idea why it behaves like this ?
>
> /Jimmy
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--001a11c3ca1467096704e217c59b
IDS 12.10.FC1 on Solaris 11 sparc
There is/was an issue with HDR regarding "SMX thread is exiting " and it does not re-establish connectivity unless the affected HDR server is restarted. (Unless it is fixed in 12.1). If that's the case then you would see the following in the msg log : 15:26:34 DR_ERR set to -1 15:26:34 SMX thread is exiting 15:26:35 DR: Turned off on secondary server Other than that my other guess is that shortly after your restore/restart the secondary (and the "HDR secondary server is operational " msg is posted in the log) the connectivity between the two servers is being dropped. If that's the case then there should be some rhetoric to that effect in the message log. It only gets posted once when connectivity drops and then again once it's re-established . Mark
Related threads
- Posting from the Informix-list
- Migrating from IDS 9.40.UC6 to 11.50.UC3
- Ip for a network session
- questions onstat -g