O processo de criação de um novo Database no ExaCS é bem simples e costuma ser rápido, levando cerca de 15 a 20 minutos para completar a operação. No entanto, o log exibido na console (detalhamento da work request) não apresenta todas etapas do processo, dificultando qualquer análise básica quando ocorre uma falha durante o processo. Este post apresenta uma dica sobre como acompanhar o progresso dessas operações através dos logs disponíveis no sistema operacional do Exadata Cloud Service.
Abaixo um exemplo do log apresentado na console durante a criação de um novo Database com falha, a mensagem apenas retorna uma informação genérica e um ID de requisição que pode ser usado para abrir uma SR no My Oracle Support:
Criando um Novo Database
Na console OCI, acesse a opção Create Database. Para este exemplo, o DB_NAME será ORCL e o DB_UNIQUE_NAME será ORCL_teste.
Após finalizar o formulário e clicar em Create Database, podemos visualizar a Work Request da operação, note que em “Log messages” é exibido somente as etapas macro do processo, sem nenhum detalhamento do que realmente o processo está fazendo em background.
Acessando o Log do DBAASCLI
DBAASCLI é o utilitário que permite executar algumas atividades administrativas do ExaCS via linha de comando (criação de databases, db homes, patches, TDE, etc), tendo uma usabilidade similar ao dbcli, presente nos DB Systems
O primeiro ponto para se saber é que a operação de criar um novo banco pela console invoca o utilitário DBAASCLI e executa o comando “dbaascli create database .. “, passando como parâmetro algumas das informações que informamos na console.
Você pode encontrar os logs do dbaascli no diretório abaixo, conectado no primeiro node do cluster:
$ cd /var/opt/oracle/log/dbaastools_launcherObserve que existe sempre um link simbólico “dbaastools_launcher.log” apontando para o último arquivo de log gerado pelo dbaascli.
Dando um “tail” nesse arquivo alguns segundos após iniciar a operação via console, podemos ver um log similar a este, informando cada etapa do processo, onde a última etapa com iniciando com “Running” exibida no log, é aquela que ele está executando no momento.
$ tail -100f dbaastools_launcher.log
2022-05-20 20:25:07.558104 - Launcher processing
May 20, 2022 8:25:06 PM oracle.dblcm.sa.dbaastools.driver.DBaaSToolsLauncher constructApplicationCommand
INFO: Constructing command to call DBaaSToolsApplication
May 20, 2022 8:25:06 PM oracle.dbcloud.common.lib.cmd.PathProvider getJreLocation
INFO: Candidate jre locations found: [/usr/java/jdk1.8.0_331-amd64]
May 20, 2022 8:25:06 PM oracle.dbcloud.common.lib.cmd.PathProvider getJreLocation
INFO: Using candidate jre location: /usr/java/jdk1.8.0_331-amd64/jre
2022-05-20 20:25:07.558373 - Launcher execution completed
2022-05-20 20:25:07.558509 - INFO : Executing export LD_LIBRARY_PATH=/var/opt/oracle/dbaastools/sa/lib;/usr/java/jdk1.8.0_331-amd64/jre/bin/java -cp /var/opt/oracle/dbaastools/sa/jlib/dbaastools-composite.jar oracle.dblcm.sa.dbaastools.driver.DBaaSToolsApplication 'database' 'create' --agent_db_id '6752fb15-a282-4009-a276-f100e7e41198' --dbName 'ORCL' --dbLanguage 'AMERICAN' --dbNCharset 'AL16UTF16' --pdbAdminUserName 'pdbuser' --agentJobId 'b038d372-7a61-42c6-b8bc-95aeffa181de' --dbCharset 'WE8ISO8859P1' --honorNodeNumberForInstance 'true' --oracleHomeName 'OraHome2' --dbSID 'ORCL' --pdbName 'pdb1' --dbTerritory 'AMERICA' --dbUniqueName 'ORCL_teste' --createAsCDB 'true'
2022-05-20 20:25:09.114744 - Job id: b038d372-7a61-42c6-b8bc-95aeffa181de
2022-05-20 20:25:09.367944 - Enter SYS_PASSWORD:
2022-05-20 20:25:09.370083 - Enter SYS_PASSWORD (reconfirmation):
2022-05-20 20:25:09.371853 - Enter TDE_PASSWORD:
2022-05-20 20:25:09.373538 - Enter TDE_PASSWORD (reconfirmation):
2022-05-20 20:25:09.387156 - Loading PILOT...
2022-05-20 20:25:10.484484 - Enter SYS_PASSWORD
2022-05-20 20:25:10.490586**************************************************
2022-05-20 20:25:10.493411 - Enter SYS_PASSWORD (reconfirmation):
2022-05-20 20:25:10.49****************************************************
2022-05-20 20:25:10.500746 - Enter TDE_PASSWORD
2022-05-20 20:25:10.506**************************************************
2022-05-20 20:25:10.509195 - Enter TDE_PASSWORD (reconfirmation):
2022-05-20 20:25:10.51**************************************************
2022-05-20 20:25:10.520282 - Session ID of the current execution is: 30
2022-05-20 20:25:10.526872 - Log file location: /var/opt/oracle/log/ORCL/database/create/pilot_2022-05-20_08-25-10-PM
2022-05-20 20:25:10.528195 - -----------------
2022-05-20 20:25:10.530665 - Running Plugin_initialization job
2022-05-20 20:25:17.516206 - Completed Plugin_initialization job
2022-05-20 20:25:18.177392 - -----------------
2022-05-20 20:25:18.180589 - Running Default_value_initialization job
2022-05-20 20:25:25.676516 - Completed Default_value_initialization job
2022-05-20 20:25:25.959070 - -----------------
2022-05-20 20:25:25.962354 - Running Validate_input_params job
2022-05-20 20:25:25.965496 - Completed Validate_input_params job
2022-05-20 20:25:26.219074 - -----------------
2022-05-20 20:25:26.221970 - Running Validate_cpu_availability job
2022-05-20 20:25:26.225020 - Completed Validate_cpu_availability job
2022-05-20 20:25:26.473990 - -----------------
2022-05-20 20:25:26.477211 - Running Validate_asm_availability job
2022-05-20 20:25:27.293118 - Completed Validate_asm_availability job
2022-05-20 20:25:27.560401 - -----------------
2022-05-20 20:25:27.563735 - Running Validate_disk_space_availability job
2022-05-20 20:25:32.000904 - Completed Validate_disk_space_availability job
2022-05-20 20:25:32.253530 - -----------------
2022-05-20 20:25:32.258260 - Running validate_users_umask job
2022-05-20 20:25:32.602264 - Completed validate_users_umask job
2022-05-20 20:25:32.855441 - -----------------
2022-05-20 20:25:32.858778 - Running Validate_huge_pages_availability job
2022-05-20 20:25:35.329067 - Completed Validate_huge_pages_availability job
2022-05-20 20:25:35.579009 - -----------------
2022-05-20 20:25:35.581372 - Running Validate_hostname_domain job
2022-05-20 20:25:35.586620 - Completed Validate_hostname_domain job
2022-05-20 20:25:35.831218 - -----------------
2022-05-20 20:25:35.833920 - Running Perform_dbca_prechecks job
2022-05-20 20:26:09.586473 - Completed Perform_dbca_prechecks job
2022-05-20 20:26:09.832220 - -----------------
2022-05-20 20:26:09.834535 - Running DB_creation_acquire_lock job
2022-05-20 20:26:10.203698 - Completed DB_creation_acquire_lock job
2022-05-20 20:26:10.441825 - -----------------
2022-05-20 20:26:10.443942 - Running Setup_acfs_volumes job
2022-05-20 20:26:11.321398 - Completed Setup_acfs_volumes job
2022-05-20 20:26:11.572965 - -----------------
2022-05-20 20:26:11.574886 - Running Setup_db_folders job
2022-05-20 20:26:13.106218 - Completed Setup_db_folders job
2022-05-20 20:26:13.356396 - -----------------
2022-05-20 20:26:13.358147 - Running DB_creation jobAcessando o Log do DBCA
Quando o log do dbaascli alcançar a etapa “Running DB_creation”, então o mesmo irá invocar o DBCA (DataBase Creation Assistant) para realizar a criação do banco de dados, note que as etapas anteriores são apenas validações de pré requisitos do ExaCS.
Nesta etapa, para se ter um nível melhor de detalhe sobre o progresso de criação do banco de dados, podemos acessar o log do DBCA que fica no diretório com o seguinte padrão:
<ORACLE_BASE>/cfgtoollogs/dbca/<DB_UNIQUE_NAME>Por padrão, o ORACLE_BASE no ExaCS é “/u02/app/oracle”, e neste exemplo que estamos criando um banco tendo o valor “ORCL_teste” como DB_UNIQUE_NAME, o diretório seria:
$ cd /u02/app/oracle/cfgtoollogs/dbca/ORCL_testeEste diretório terá vários arquivos de log do DBCA, mas o percentual de progresso fica no arquivo <DB_UNIQUE_NAME>.log:
$ cat ORCL_teste.log
[ 2022-05-20 20:26:21.883 BRT ] Prepare for db operation
DBCA_PROGRESS : 7%
[ 2022-05-20 20:26:28.430 BRT ] Copying database files
DBCA_PROGRESS : 27%
[ 2022-05-20 20:29:36.697 BRT ] Creating and starting Oracle instance
DBCA_PROGRESS : 28%
DBCA_PROGRESS : 31%
DBCA_PROGRESS : 35%
DBCA_PROGRESS : 37%
DBCA_PROGRESS : 40%
[ 2022-05-20 20:32:48.948 BRT ] Creating cluster database views
DBCA_PROGRESS : 41%
DBCA_PROGRESS : 53%
[ 2022-05-20 20:33:39.058 BRT ] Completing Database Creation
[ 2022-05-20 20:33:43.775 BRT ] [WARNING] Datapatch execution has failed. Make sure to rerun the datapatch after database operation. Look at the datapatch logs in "/u02/app/oracle/cfgtoollogs/sqlpatch" for further details.
DBCA_PROGRESS : 57%
DBCA_PROGRESS : 59%
DBCA_PROGRESS : 60%
[ 2022-05-20 20:35:58.137 BRT ] Creating Pluggable DatabasesQuando o log do DBCA indicar 100% concluído, podemos voltar a monitorar o log do dbaascli:
$ tail -100f dbaastools_launcher.log
2022-05-20 20:36:25.644069 - -----------------
2022-05-20 20:36:25.646844 - Running DB_creation_release_lock job
2022-05-20 20:36:26.232595 - Completed DB_creation_release_lock job
2022-05-20 20:36:26.475663 - -----------------
2022-05-20 20:36:26.477661 - Running Load_db_details job
2022-05-20 20:36:28.720219 - Completed Load_db_details job
2022-05-20 20:36:28.991281 - -----------------
2022-05-20 20:36:28.993646 - Running Populate_creg job
2022-05-20 20:36:43.513161 - Completed Populate_creg job
2022-05-20 20:36:43.764162 - -----------------
2022-05-20 20:36:43.766257 - Running Register_ocids job
2022-05-20 20:36:43.769946 - Skipping. Job is detected as not applicable.
2022-05-20 20:36:44.005467 - -----------------
2022-05-20 20:36:44.008570 - Running Create_users_tablespace job
2022-05-20 20:36:44.993252 - Completed Create_users_tablespace job
2022-05-20 20:36:45.245464 - -----------------
2022-05-20 20:36:45.248080 - Running Configure_pdb_service job
2022-05-20 20:36:47.344787 - Completed Configure_pdb_service job
2022-05-20 20:36:47.599250 - -----------------
2022-05-20 20:36:47.602671 - Running Set_pdb_admin_user_profile job
2022-05-20 20:36:47.848601 - Completed Set_pdb_admin_user_profile job
2022-05-20 20:36:48.087564 - -----------------
2022-05-20 20:36:48.089793 - Running Lock_pdb_admin_user job
2022-05-20 20:36:48.154272 - Completed Lock_pdb_admin_user job
2022-05-20 20:36:48.392639 - -----------------
2022-05-20 20:36:48.395137 - Running Configure_flashback job
2022-05-20 20:37:02.767658 - Completed Configure_flashback job
2022-05-20 20:37:03.013203 - -----------------
2022-05-20 20:37:03.016113 - Running Configure_undo_retention job
2022-05-20 20:37:03.189583 - Completed Configure_undo_retention job
2022-05-20 20:37:03.430378 - -----------------
2022-05-20 20:37:03.436813 - Running Update_cloud_service_recommended_config_parameters job
2022-05-20 20:37:03.940704 - Completed Update_cloud_service_recommended_config_parameters job
2022-05-20 20:37:04.175832 - -----------------
2022-05-20 20:37:04.179183 - Running Update_distributed_lock_timeout job
2022-05-20 20:37:04.274825 - Completed Update_distributed_lock_timeout job
2022-05-20 20:37:04.516920 - -----------------
2022-05-20 20:37:04.519575 - Running Configure_archiving job
2022-05-20 20:37:04.619416 - Completed Configure_archiving job
2022-05-20 20:37:04.859157 - -----------------
2022-05-20 20:37:04.861659 - Running Configure_huge_pages job
2022-05-20 20:37:04.958463 - Completed Configure_huge_pages job
2022-05-20 20:37:05.201291 - -----------------
2022-05-20 20:37:05.203462 - Running Set_credentials job
2022-05-20 20:37:05.849100 - Completed Set_credentials job
2022-05-20 20:37:06.096739 - -----------------
2022-05-20 20:37:06.099531 - Running Update_dba_directories job
2022-05-20 20:37:06.659417 - Completed Update_dba_directories job
2022-05-20 20:37:06.905827 - -----------------
2022-05-20 20:37:06.909038 - Running Set_cluster_interconnects job
2022-05-20 20:37:08.160493 - Completed Set_cluster_interconnects job
2022-05-20 20:37:08.400105 - -----------------
2022-05-20 20:37:08.402812 - Running Create_db_secure_profile job
2022-05-20 20:37:09.914678 - Completed Create_db_secure_profile job
2022-05-20 20:37:10.173797 - -----------------
2022-05-20 20:37:10.176306 - Running Set_utc_timezone job
2022-05-20 20:37:10.261725 - Completed Set_utc_timezone job
2022-05-20 20:37:10.500797 - -----------------
2022-05-20 20:37:10.503429 - Running Run_dst_post_installs job
2022-05-20 20:37:10.824400 - Completed Run_dst_post_installs job
2022-05-20 20:37:11.074005 - -----------------
2022-05-20 20:37:11.076043 - Running Enable_auditing job
2022-05-20 20:37:11.397661 - Completed Enable_auditing job
2022-05-20 20:37:11.645389 - -----------------
2022-05-20 20:37:11.648451 - Running Apply_security_measures job
2022-05-20 20:37:12.643571 - Completed Apply_security_measures job
2022-05-20 20:37:12.883789 - -----------------
2022-05-20 20:37:12.886430 - Running Set_listener_init_params job
2022-05-20 20:37:14.040259 - Completed Set_listener_init_params job
2022-05-20 20:37:14.278205 - -----------------
2022-05-20 20:37:14.280225 - Running Update_db_wallet job
2022-05-20 20:37:16.201929 - Completed Update_db_wallet job
2022-05-20 20:37:16.437717 - -----------------
2022-05-20 20:37:16.439983 - Running Add_oratab_entry job
2022-05-20 20:37:19.095014 - Completed Add_oratab_entry job
2022-05-20 20:37:19.331060 - -----------------
2022-05-20 20:37:19.333223 - Running Configure_sqlnet_ora job
2022-05-20 20:37:24.396539 - Completed Configure_sqlnet_ora job
2022-05-20 20:37:24.627687 - -----------------
2022-05-20 20:37:24.630156 - Running Configure_tnsnames_ora job
2022-05-20 20:37:28.911141 - Completed Configure_tnsnames_ora job
2022-05-20 20:37:29.147077 - -----------------
2022-05-20 20:37:29.148874 - Running Enable_fips job
2022-05-20 20:37:29.150711 - Completed Enable_fips job
2022-05-20 20:37:29.381843 - -----------------
2022-05-20 20:37:29.384396 - Running DB_backup_assistant job
2022-05-20 20:37:48.109861 - Completed DB_backup_assistant job
2022-05-20 20:37:48.348702 - -----------------
2022-05-20 20:37:48.350900 - Running Restart_database job
2022-05-20 20:38:51.087360 - Completed Restart_database job
2022-05-20 20:38:51.330567 - -----------------
2022-05-20 20:38:51.333507 - Running Create_db_login_environment_file job
2022-05-20 20:38:53.125595 - Completed Create_db_login_environment_file job
2022-05-20 20:38:53.360540 - -----------------
2022-05-20 20:38:53.363499 - Running Generate_dbsystem_details job
2022-05-20 20:39:17.959884 - Completed Generate_dbsystem_details job
2022-05-20 20:39:18.195010 - -----------------
2022-05-20 20:39:18.196521 - Running Cleanup job
2022-05-20 20:39:19.666940 - Completed Cleanup job
2022-05-20 20:39:20.750540 - dbaascli execution completedQuando o log do dbaascli completar a etapa “Cleanup”, alguns segundos depois a console já deve mostrar o status do Database como Available:
Conclusão
Este post apresentou mais uma dica rápida para DBAs que já possuem um conhecimento básico do ExaCS e desejam conhecer mais o que acontece nos bastidores da console. Apesar de o exemplo ter demonstrado exclusivamente como acompanhar o progresso de criação de um novo Database, este conhecimento pode ser muito útil em atividades de throubleshooting básico.