Hi all.
(O 9.2.0.1.0)

Somehow I managed to lock up the test DB again while shutting it down.
I suspect it may have something to do with some java thread that is
started by a job, but I can't really make much of the logfiles I get.
When I issue a sc stop OracleServiceSID on windows (xp) this will do a
Shutdown Immediate.
This is what I did, but after an hour the shutdown is still in progress
and I'm very sure that this cannot be due to something big being rolled
back, since there isn't anything big going on in the system.

When I look at the logfiles I can just see that the shutdown is in
progress and one job (the one that started a java thread) seems not to
terminate (the other jobs have traced out ORA-01089 + ORA-00448).

Find the last entries of said logfiles below.
Maybe someone can shed a bit more light on this or tell me where to go
looking for more info.

thanks!
Martin

sc stop OracleServiceFIP ... issued approx. 12:00

(Files as of 12:50)

bdump/alert.log [last modf. 12:09]
----------------------------------
....
Wed Nov 22 12:04:38 2006
Shutting down instance: further logons disabled
Shutting down instance (immediate)
License high water mark = 37
Wed Nov 22 12:04:57 2006
Thread 1 advanced to log sequence 2016
Current log# 3 seq# 2016 mem# 0: C:\ORACLE\ORADATA\FIP\REDO03.LOG
Wed Nov 22 12:09:46 2006
Active call for process 2180 user 'SYSTEM' program 'ORACLE.EXE (J000)'
SHUTDOWN: waiting for active calls to complete.


udump/fip_j000_2180.trc [last modf. 12:04]
----------------------------------
....
Error: collecting cyclic machine data using procedure
MONITOR.COLLECT_CYCLIC_MACHINE_DATA
oracle.jdbc.driver.OracleSQLException: ORA-01089: immediate shutdown in
progress - no operations are permitted
ORA-06512: at "FIP.MONITOR", line 3230
ORA-06512: at line 1
*** 2006-11-22 12:04:40.000


udump/fip_ora_2960.trc [last modf. 12:50]
----------------------------------
....
*** SESSION ID21.5982) 2006-11-22 12:09:46.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:14:54.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:20:02.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:25:10.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:30:19.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:35:26.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:40:34.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:45:42.000
SHUTDOWN: waiting for active calls to complete.
*** 2006-11-22 12:50:50.000
SHUTDOWN: waiting for active calls to complete.


trace file from another job (that seems to have terminated correctly):
-------------------------------------------------------
....
Dump file c:\oracle\admin\fip\udump\fip_j007_2784.trc
Wed Nov 22 12:04:39 2006
ORACLE V9.2.0.1.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Oracle9i Release 9.2.0.1.0 - Production
JServer Release 9.2.0.1.0 - Production
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Instance name: fip

Redo thread mounted by this instance: 1

Oracle process number: 22

Windows thread id: 2784, image: ORACLE.EXE (J007)


*** 2006-11-22 12:04:39.000
*** SESSION ID45.3276) 2006-11-22 12:04:39.000
OPIRIP: Uncaught error 1089. Error stack:
ORA-01089: immediate shutdown in progress - no operations are permitted
ORA-00448: normal completion of background process

On Nov 22, 1:09 pm, "Martin T." <bilbothebagginsb...@freenet.de>
wrote:
> Hi all.
> (O 9.2.0.1.0)
>
> Somehow I managed to lock up the test DB again while shutting it down.
> I suspect it may have something to do with some java thread that is
> started by a job, but I can't really make much of the logfiles I get.
> When I issue a sc stop OracleServiceSID on windows (xp) this will do a
> Shutdown Immediate.
> This is what I did, but after an hour the shutdown is still in progress
> and I'm very sure that this cannot be due to something big being rolled
> back, since there isn't anything big going on in the system.
>
> When I look at the logfiles I can just see that the shutdown is in
> progress and one job (the one that started a java thread) seems not to
> terminate (the other jobs have traced out ORA-01089 + ORA-00448).
>
> Find the last entries of said logfiles below.
> Maybe someone can shed a bit more light on this or tell me where to go
> looking for more info.
>
> thanks!
> Martin
>
> sc stop OracleServiceFIP ... issued approx. 12:00
>
> (Files as of 12:50)
>
> bdump/alert.log [last modf. 12:09]
> ----------------------------------
> ...
> Wed Nov 22 12:04:38 2006
> Shutting down instance: further logons disabled
> Shutting down instance (immediate)
> License high water mark = 37
> Wed Nov 22 12:04:57 2006
> Thread 1 advanced to log sequence 2016
> Current log# 3 seq# 2016 mem# 0: C:\ORACLE\ORADATA\FIP\REDO03.LOG
> Wed Nov 22 12:09:46 2006
> Active call for process 2180 user 'SYSTEM' program 'ORACLE.EXE (J000)'
> SHUTDOWN: waiting for active calls to complete.
>
> udump/fip_j000_2180.trc [last modf. 12:04]
> ----------------------------------
> ...
> Error: collecting cyclic machine data using procedure
> MONITOR.COLLECT_CYCLIC_MACHINE_DATA
> oracle.jdbc.driver.OracleSQLException: ORA-01089: immediate shutdown in
> progress - no operations are permitted
> ORA-06512: at "FIP.MONITOR", line 3230
> ORA-06512: at line 1
> *** 2006-11-22 12:04:40.000
>
> udump/fip_ora_2960.trc [last modf. 12:50]
> ----------------------------------
> ...
> *** SESSION ID21.5982) 2006-11-22 12:09:46.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:14:54.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:20:02.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:25:10.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:30:19.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:35:26.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:40:34.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:45:42.000
> SHUTDOWN: waiting for active calls to complete.
> *** 2006-11-22 12:50:50.000
> SHUTDOWN: waiting for active calls to complete.
>
> trace file from another job (that seems to have terminated correctly):
> -------------------------------------------------------
> ...
> Dump file c:\oracle\admin\fip\udump\fip_j007_2784.trc
> Wed Nov 22 12:04:39 2006
> ORACLE V9.2.0.1.0 - Production vsnsta=0
> vsnsql=12 vsnxtr=3
> Windows 2000 Version 5.1 Service Pack 2, CPU type 586
> Oracle9i Release 9.2.0.1.0 - Production
> JServer Release 9.2.0.1.0 - Production
> Windows 2000 Version 5.1 Service Pack 2, CPU type 586
> Instance name: fip
>
> Redo thread mounted by this instance: 1
>
> Oracle process number: 22
>
> Windows thread id: 2784, image: ORACLE.EXE (J007)
>
> *** 2006-11-22 12:04:39.000
> *** SESSION ID45.3276) 2006-11-22 12:04:39.000
> OPIRIP: Uncaught error 1089. Error stack:
> ORA-01089: immediate shutdown in progress - no operations are permitted
> ORA-00448: normal completion of background process


Many times I need to
alter system set job_queue_processes=0;
alter system set aq_tm_processes=0;

Even if there are no jobs running the job queue facility will poll the
queue by means of SELECTs.
MONITOR looks like a job.

Hth
--
Sybrand Bakker
Senior Oracle DBA

sybrandb wrote:
> On Nov 22, 1:09 pm, "Martin T." <bilbothebagginsb...@freenet.de>
> wrote:
> > Hi all.
> > (O 9.2.0.1.0)
> >
> > Somehow I managed to lock up the test DB again while shutting it down.
> > I suspect it may have something to do with some java thread that is
> > started by a job, but I can't really make much of the logfiles I get.
> > When I issue a sc stop OracleServiceSID on windows (xp) this will do a
> > Shutdown Immediate.
> > This is what I did, but after an hour the shutdown is still in progress
> > and I'm very sure that this cannot be due to something big being rolled
> > back, since there isn't anything big going on in the system.
> >
> > When I look at the logfiles I can just see that the shutdown is in
> > progress and one job (the one that started a java thread) seems not to
> > terminate (the other jobs have traced out ORA-01089 + ORA-00448).
> >
> > Find the last entries of said logfiles below.
> > Maybe someone can shed a bit more light on this or tell me where to go
> > looking for more info.
> >
> > thanks!
> > Martin
> >
> > [snipped]
>
> Many times I need to
> alter system set job_queue_processes=0;
> alter system set aq_tm_processes=0;
>
> Even if there are no jobs running the job queue facility will poll the
> queue by means of SELECTs.
> MONITOR looks like a job.
>
> Hth

Sybrand, thanks.

It seems that I was too rash in stating it hangs, it shut down approx.
10 minutes after I posted here. (Which still leaves 1 hour of mystery
:-)

It was most likely a job that hung, aq_tm_processes=0 is set anyway.
The job in question starts some java that starts some multithreaded
work that is run every few seconds. (It's not much to do, basically one
table row is updated.)

What was strange, is that the trace file of j000 that had a last
modification date of 12:09 in my OP was the last file that was closed
by oracle.exe (13:09 or so). But nothing new was written into it.

So it apears that oracle started to log into the file and then waited
for one hour (doing not much, or at least nothing worth logging) and
then closed the logfile and exited.

I'm still confused I'm afraid ...

cheers,
Martin

Martin T. wrote:
> sybrandb wrote:
> > On Nov 22, 1:09 pm, "Martin T." <bilbothebagginsb...@freenet.de>
> > wrote:
> > > Hi all.
> > > (O 9.2.0.1.0)
> > >
> > > Somehow I managed to lock up the test DB again while shutting it down.
> > > I suspect it may have something to do with some java thread that is
> > > started by a job, but I can't really make much of the logfiles I get.
> > > When I issue a sc stop OracleServiceSID on windows (xp) this will do a
> > > Shutdown Immediate.
> > > This is what I did, but after an hour the shutdown is still in progress
> > > and I'm very sure that this cannot be due to something big being rolled
> > > back, since there isn't anything big going on in the system.
> > >
> > > When I look at the logfiles I can just see that the shutdown is in
> > > progress and one job (the one that started a java thread) seems not to
> > > terminate (the other jobs have traced out ORA-01089 + ORA-00448).
> > >
> > > Find the last entries of said logfiles below.
> > > Maybe someone can shed a bit more light on this or tell me where to go
> > > looking for more info.
> > >
> > > thanks!
> > > Martin
> > >
> > > [snipped]
> >
> > Many times I need to
> > alter system set job_queue_processes=0;
> > alter system set aq_tm_processes=0;
> >
> > Even if there are no jobs running the job queue facility will poll the
> > queue by means of SELECTs.
> > MONITOR looks like a job.
> >
> > Hth
>
> Sybrand, thanks.
>
> It seems that I was too rash in stating it hangs, it shut down approx.
> 10 minutes after I posted here. (Which still leaves 1 hour of mystery
> :-)
>
> It was most likely a job that hung, aq_tm_processes=0 is set anyway.
> The job in question starts some java that starts some multithreaded
> work that is run every few seconds. (It's not much to do, basically one
> table row is updated.)
>
> What was strange, is that the trace file of j000 that had a last
> modification date of 12:09 in my OP was the last file that was closed
> by oracle.exe (13:09 or so). But nothing new was written into it.
>
> So it apears that oracle started to log into the file and then waited
> for one hour (doing not much, or at least nothing worth logging) and
> then closed the logfile and exited.
>
> I'm still confused I'm afraid ...
>
> cheers,
> Martin

Were the any active transactions? Rolback can take a long time.

Martin T. wrote:
>
> It seems that I was too rash in stating it hangs, it shut down approx.
> 10 minutes after I posted here. (Which still leaves 1 hour of mystery
> :-)
>
> It was most likely a job that hung, aq_tm_processes=0 is set anyway.
> The job in question starts some java that starts some multithreaded
> work that is run every few seconds. (It's not much to do, basically one
> table row is updated.)
>
> What was strange, is that the trace file of j000 that had a last
> modification date of 12:09 in my OP was the last file that was closed
> by oracle.exe (13:09 or so). But nothing new was written into it.
>
> So it apears that oracle started to log into the file and then waited
> for one hour (doing not much, or at least nothing worth logging) and
> then closed the logfile and exited.
>
> I'm still confused I'm afraid ...
>
> cheers,
> Martin

Oracle at least historically on windows used to have lots of problems
with shutdowns.

I would hope that by now almost all of those types of bugs have now
been addressed by oracle fixes. It didn't appear to me that you were
patched anywere close the "final" 9208 patchset so that's possibly one
item you might want to consider.