oci-oracle-xe
oci-oracle-xe copied to clipboard
gvenzl
"cannot allocate new log" shown 40x after startup
Docker image started with:
docker run -it --network=host -eORACLE_PASSWORD=atk4_pass gvenzl/oracle-xe:slim
shows 40x cannot allocate new log, full startup log:
Unable to find image 'gvenzl/oracle-xe:slim' locally
slim: Pulling from gvenzl/oracle-xe
f4069ceb7689: Pull complete
50b5143a8e9f: Pull complete
Digest: sha256:18031ac2c6e5881ef8f7ee4d40cd4cf6152fa4837e12bc4c2132791393a71335
Status: Downloaded newer image for gvenzl/oracle-xe:slim
CONTAINER: starting up...
CONTAINER: first database startup, initializing...
CONTAINER: uncompressing database data files, please wait...
CONTAINER: done uncompressing database data files, duration: 19 seconds.
CONTAINER: starting up Oracle Database...
LSNRCTL for Linux: Version 21.0.0.0.0 - Production on 10-JUL-2022 21:24:33
Copyright (c) 1991, 2021, Oracle. All rights reserved.
Starting /opt/oracle/product/21c/dbhomeXE/bin/tnslsnr: please wait...
TNSLSNR for Linux: Version 21.0.0.0.0 - Production
System parameter file is /opt/oracle/homes/OraDBHome21cXE/network/admin/listener.ora
Log messages written to /opt/oracle/diag/tnslsnr/debianxx/listener/alert/log.xml
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_XE)))
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=0.0.0.0)(PORT=1521)))
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC_FOR_XE)))
STATUS of the LISTENER
------------------------
Alias LISTENER
Version TNSLSNR for Linux: Version 21.0.0.0.0 - Production
Start Date 10-JUL-2022 21:24:33
Uptime 0 days 0 hr. 0 min. 0 sec
Trace Level off
Security ON: Local OS Authentication
SNMP OFF
Default Service XE
Listener Parameter File /opt/oracle/homes/OraDBHome21cXE/network/admin/listener.ora
Listener Log File /opt/oracle/diag/tnslsnr/debianxx/listener/alert/log.xml
Listening Endpoints Summary...
(DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_XE)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=0.0.0.0)(PORT=1521)))
The listener supports no services
The command completed successfully
ORACLE instance started.
Total System Global Area 1241512272 bytes
Fixed Size 9685328 bytes
Variable Size 671088640 bytes
Database Buffers 553648128 bytes
Redo Buffers 7090176 bytes
Database mounted.
Database opened.
CONTAINER: Resetting SYS and SYSTEM passwords.
User altered.
User altered.
#########################
DATABASE IS READY TO USE!
#########################
##################################################################
CONTAINER: The following output is now from the alert_XE.log file:
##################################################################
Using default pga_aggregate_limit of 2048 MB
2022-07-10T21:24:40.738581+00:00
Resize operation completed for file# 201, fname /opt/oracle/oradata/XE/temp01.dbf, old size 2048K, new size 12288K
2022-07-10T21:24:40.777660+00:00
XEPDB1(3):Opening pdb with Resource Manager plan: DEFAULT_PLAN
Pluggable database XEPDB1 opened read write
Starting background process CJQ0
2022-07-10T21:24:41.133230+00:00
CJQ0 started with pid=59, OS id=206
Completed: ALTER DATABASE OPEN
2022-07-10T21:24:46.057054+00:00
Begin automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK"
End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK"
2022-07-10T21:24:52.058430+00:00
TABLE SYS.WRI$_OPTSTAT_HISTHEAD_HISTORY: ADDED INTERVAL PARTITION SYS_P381 (44751) VALUES LESS THAN (TO_DATE(' 2022-07-11 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
TABLE SYS.WRI$_OPTSTAT_HISTGRM_HISTORY: ADDED INTERVAL PARTITION SYS_P384 (44751) VALUES LESS THAN (TO_DATE(' 2022-07-11 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
2022-07-10T21:24:52.727922+00:00
Thread 1 advanced to log sequence 20 (LGWR switch), current SCN: 2962825
Current log# 1 seq# 20 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:24:56.504223+00:00
XEPDB1(3):TABLE SYS.WRI$_OPTSTAT_HISTHEAD_HISTORY: ADDED INTERVAL PARTITION SYS_P360 (44751) VALUES LESS THAN (TO_DATE(' 2022-07-11 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
XEPDB1(3):TABLE SYS.WRI$_OPTSTAT_HISTGRM_HISTORY: ADDED INTERVAL PARTITION SYS_P363 (44751) VALUES LESS THAN (TO_DATE(' 2022-07-11 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
2022-07-10T21:25:00.039967+00:00
Thread 1 cannot allocate new log, sequence 21
Checkpoint not complete
Current log# 1 seq# 20 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:01.925557+00:00
Thread 1 advanced to log sequence 21 (LGWR switch), current SCN: 2969438
Current log# 2 seq# 21 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:07.606041+00:00
Thread 1 cannot allocate new log, sequence 22
Checkpoint not complete
Current log# 2 seq# 21 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:08.077260+00:00
Thread 1 advanced to log sequence 22 (LGWR switch), current SCN: 2973441
Current log# 1 seq# 22 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:11.946137+00:00
Thread 1 cannot allocate new log, sequence 23
Checkpoint not complete
Current log# 1 seq# 22 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:14.206450+00:00
Thread 1 advanced to log sequence 23 (LGWR switch), current SCN: 2976209
Current log# 2 seq# 23 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:14.872769+00:00
XEPDB1(3):Resize operation completed for file# 9, fname /opt/oracle/oradata/XE/XEPDB1/system01.dbf, old size 278528K, new size 288768K
2022-07-10T21:25:18.147042+00:00
Thread 1 advanced to log sequence 24 (LGWR switch), current SCN: 2980549
Current log# 1 seq# 24 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:21.240215+00:00
Resize operation completed for file# 15, fname /opt/oracle/oradata/XE/undotbs01.dbf, old size 11264K, new size 21504K
2022-07-10T21:25:23.683354+00:00
Thread 1 advanced to log sequence 25 (LGWR switch), current SCN: 2990113
Current log# 2 seq# 25 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:23.941460+00:00
XEPDB1(3):Resize operation completed for file# 19, fname /opt/oracle/oradata/XE/XEPDB1/undotbs01.dbf, old size 11264K, new size 21504K
2022-07-10T21:25:27.971681+00:00
Thread 1 cannot allocate new log, sequence 26
Checkpoint not complete
Current log# 2 seq# 25 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:29.321598+00:00
Thread 1 advanced to log sequence 26 (LGWR switch), current SCN: 2999892
Current log# 1 seq# 26 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:33.515032+00:00
Thread 1 cannot allocate new log, sequence 27
Checkpoint not complete
Current log# 1 seq# 26 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:35.456599+00:00
Thread 1 advanced to log sequence 27 (LGWR switch), current SCN: 3006386
Current log# 2 seq# 27 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:39.160743+00:00
Resize operation completed for file# 15, fname /opt/oracle/oradata/XE/undotbs01.dbf, old size 21504K, new size 31744K
2022-07-10T21:25:40.158717+00:00
Thread 1 cannot allocate new log, sequence 28
Checkpoint not complete
Current log# 2 seq# 27 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:41.600182+00:00
Thread 1 advanced to log sequence 28 (LGWR switch), current SCN: 3011691
Current log# 1 seq# 28 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:46.838579+00:00
Thread 1 cannot allocate new log, sequence 29
Checkpoint not complete
Current log# 1 seq# 28 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:47.832570+00:00
Thread 1 advanced to log sequence 29 (LGWR switch), current SCN: 3015682
Current log# 2 seq# 29 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:53.357158+00:00
Thread 1 cannot allocate new log, sequence 30
Checkpoint not complete
Current log# 2 seq# 29 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:25:53.890971+00:00
Thread 1 advanced to log sequence 30 (LGWR switch), current SCN: 3019927
Current log# 1 seq# 30 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:25:54.160208+00:00
XEPDB1(3):Resize operation completed for file# 19, fname /opt/oracle/oradata/XE/XEPDB1/undotbs01.dbf, old size 21504K, new size 31744K
2022-07-10T21:25:58.756381+00:00
Thread 1 cannot allocate new log, sequence 31
Checkpoint not complete
Current log# 1 seq# 30 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:00.034289+00:00
Thread 1 advanced to log sequence 31 (LGWR switch), current SCN: 3023950
Current log# 2 seq# 31 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:05.426334+00:00
Thread 1 cannot allocate new log, sequence 32
Checkpoint not complete
Current log# 2 seq# 31 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:06.177942+00:00
Thread 1 advanced to log sequence 32 (LGWR switch), current SCN: 3028490
Current log# 1 seq# 32 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:12.405224+00:00
Thread 1 advanced to log sequence 33 (LGWR switch), current SCN: 3032684
Current log# 2 seq# 33 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:17.720163+00:00
Thread 1 cannot allocate new log, sequence 34
Checkpoint not complete
Current log# 2 seq# 33 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:18.470576+00:00
Thread 1 advanced to log sequence 34 (LGWR switch), current SCN: 3037345
Current log# 1 seq# 34 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:21.523672+00:00
XEPDB1(3):Resize operation completed for file# 19, fname /opt/oracle/oradata/XE/XEPDB1/undotbs01.dbf, old size 31744K, new size 41984K
2022-07-10T21:26:23.845718+00:00
Resize operation completed for file# 15, fname /opt/oracle/oradata/XE/undotbs01.dbf, old size 31744K, new size 41984K
2022-07-10T21:26:23.903268+00:00
Thread 1 cannot allocate new log, sequence 35
Checkpoint not complete
Current log# 1 seq# 34 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:24.551122+00:00
Thread 1 advanced to log sequence 35 (LGWR switch), current SCN: 3041830
Current log# 2 seq# 35 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:29.554536+00:00
Thread 1 cannot allocate new log, sequence 36
Checkpoint not complete
Current log# 2 seq# 35 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:30.757266+00:00
Thread 1 advanced to log sequence 36 (LGWR switch), current SCN: 3046554
Current log# 1 seq# 36 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:35.688192+00:00
Thread 1 cannot allocate new log, sequence 37
Checkpoint not complete
Current log# 1 seq# 36 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:36.901134+00:00
Thread 1 advanced to log sequence 37 (LGWR switch), current SCN: 3051513
Current log# 2 seq# 37 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:42.050667+00:00
Thread 1 cannot allocate new log, sequence 38
Checkpoint not complete
Current log# 2 seq# 37 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:43.042523+00:00
Thread 1 advanced to log sequence 38 (LGWR switch), current SCN: 3060414
Current log# 1 seq# 38 mem# 0: /opt/oracle/oradata/XE/redo01.log
2022-07-10T21:26:53.105060+00:00
Thread 1 advanced to log sequence 39 (LGWR switch), current SCN: 3065326
Current log# 2 seq# 39 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:26:55.327851+00:00
Resize operation completed for file# 15, fname /opt/oracle/oradata/XE/undotbs01.dbf, old size 41984K, new size 52224K
2022-07-10T21:29:50.070463+00:00
Thread 1 cannot allocate new log, sequence 40
Checkpoint not complete
Current log# 2 seq# 39 mem# 0: /opt/oracle/oradata/XE/redo02.log
2022-07-10T21:29:50.360527+00:00
Thread 1 advanced to log sequence 40 (LGWR switch), current SCN: 3072795
Current log# 1 seq# 40 mem# 0: /opt/oracle/oradata/XE/redo01.log
which takes full 5 minutes, before the image gives up. There should be not such errors after clean startup.
Hi @mvorisek,
Thanks for reporting this and for using these images. What you see here is the output of the database alert log.
#########################
DATABASE IS READY TO USE!
#########################
##################################################################
CONTAINER: The following output is now from the alert_XE.log file:
##################################################################
Using default pga_aggregate_limit of 2048 MB
2022-07-10T21:24:40.738581+00:00
Resize operation completed for file# 201, fname /opt/oracle/oradata/XE/temp01.dbf, old size 2048K, new size 12288K
2022-07-10T21:24:40.777660+00:00
XEPDB1(3):Opening pdb with Resource Manager plan: DEFAULT_PLAN
Pluggable database XEPDB1 opened read write
Starting background process CJQ0
2022-07-10T21:24:41.133230+00:00
CJQ0 started with pid=59, OS id=206
Completed: ALTER DATABASE OPEN
2022-07-10T21:24:46.057054+00:00
These are not errors of the image but just the log file of the database itself that is being tailed. The database is long ready to use and to accept connections as printed above.
which takes full 5 minutes, before the image gives up.
Perhaps you expected the image to no longer print any messages after it's fully started up. That will not be the case, once the database is started up it tails the database alert log so that users can quickly assess the status of the database via docker log.
Usually, containers are started in detached mode (regardless of what software runs inside the container) and users do not care much what shows in the container log (docker log). Perhaps you meant to start the container via docker run -d --network=host -e ORACLE_PASSWORD=atk4_pass gvenzl/oracle-xe:slim?
Hi @gvenzl
I started the image with docker run -it as I needed the image for development purposes for https://github.com/atk4/data. This usecase needs the fastest startup possible and I start/keep the image in foreground - once I am done with the debug, I press simply ctrl+c to stop it.
Yes, the logs are for informational purposes, but I do not expect them. They make "checking when the DB is ready visually" almost impossible.
Also when there are some meaningful messages during the "5 minutes startup" printed, they are burries in these info logs.
Is there any possibility to fix the Docker image so the database does not need to resize once it is started? Maybe it can be resized during build.
Hi @mvorisek,
I see, that makes sense.
Unfortunately, there is no easy way to suppress these messages, however, whenever you see them, the database is definitely ready as they are not printed until after the database is running.
The resize on startup is done to keep the image size itself small, something that has been requested a lot. However, the image could be extended with an already resized database, that way the startup time will be less.
Hope this helps!
The resize on startup is done to keep the image size itself small, something that has been requested a lot. However, the image could be extended with an already resized database, that way the startup time will be less.
There are "two Docker image sizes". One compressed (for transport/download), one uncompressed (done immediatelly after download).
If the image will be resized during build, would this increase the compressed size as well?
If not, or not much, the resize should be done during the image build. Larger uncompressed/local size is not an issue, as larger size is needed when run anyway.
No, the compressed size stays the same. Nevertheless, many people have complained that the uncompressed image size on disk was too big. I also never understood why this is such a big deal but users seem to care a lot about the image sizes on disk. Thanks for joining the conversation in #36 btw.
many people have complained that the uncompressed image size on disk was too big.
I tried to lookup discussion for it but in this repo's issues I did not find any mention. Do you speak about some feedback for other repo?
If it was some feedback from one, two people, maybe we should educate them the transport size isn't related to the uncompressed image size instead.
The discussions were in many places on the internet over many years. It was unfortunately not just a couple of people but the majority of them. Originally I started out with a fully expanded database inside the image (before I built these images), and people weren't happy. You can find some, by now very old, comments regarding image size, for example here or here. But there are many more scattered over Twitter and other places too.
The best approach will probably be to offer both variants going forward and let people decide which one to use, but it means an additional storage requirement on the Docker Hub repo which I'm actually not quite sure what the current limit is.
Hi Gerald,
I saw your https://github.com/gvenzl/oci-oracle-xe/issues/36#issuecomment-1229347105 post about expanded images and I was hoping it will solve also this issue, but it does not.
The problem of cannot allocate new log in log remains.
Can you reproduce it with:
docker run -it --network=host -eORACLE_PASSWORD=atk4_pass gvenzl/oracle-xe:slim-faststart
on your side?
It seems the only change of -faststart images is unzip is run in an extra Docker layer https://github.com/gvenzl/oci-oracle-xe/commit/23a61dea00b7e3110ebf65778dc830978ac83082#diff-6a620a5cf99560fb17fd003ad2aed6a61e6de3385b5c39002c2b961057178052R25 .
Looking further where the zip file is created - https://github.com/gvenzl/oci-oracle-xe/blob/23a61dea00b7e3110ebf65778dc830978ac83082/install.1840.sh#L894 - I have idea of two places where this issue can come from:
- from some cleanup in https://github.com/gvenzl/oci-oracle-xe/blob/23a61dea00b7e3110ebf65778dc830978ac83082/install.1840.sh#L932
- or maybe here https://github.com/gvenzl/oci-oracle-xe/blob/23a61dea00b7e3110ebf65778dc830978ac83082/install.1840.sh#L879 the resizing is done after the DB is ready in asynchronous fashion - so maybe we need to wait like 15 minutes before shutdown to allow the Oracle DB to resize before we zip it?
Hi @mvorisek,
You are correct, the fix in #36 does not change the output from the alert log.
This output is wanted, it's the database log file itself and it needs to be printed to stdout so that a user can interrogate the state of the database via a docker logs or similar on K8s, OpenShift, etc.