none
File di log cresciuti a dismisura (forse dipendente da SQL AlwaysOn) RRS feed

  • Domanda

  • Un paio di database configurati in AlwaysOn su due server (e su due istanze diverse e quindi anche diversi gruppi di AlwaysOn) improvvisamente vede crescere i propri log fino ad esaurire lo spazio disco... e a quanto mi viene detto si tratta di database praticamente non utilizzati (uno serve una installazione di test di una applicazione e l'altro contiene dati molto vecchi raramente acceduti in sola lettura).

    Ho il sospetto che dipenda da qualche problema di AlwaysOn... come posso capire cosa causa l'aumento improvviso dei log di questi DB?

    Ciao,


    Dario Palermo

    giovedì 9 gennaio 2020 11:34

Risposte

Tutte le risposte

  • Prova a guardare:

    1. I logs di SQL Server

    2. L'event viewer Application della macchina di SQL Server.

    3. Gli altri event viewer sempre della macchina di SQL Server.


    Massimo Giambona MCT

    venerdì 10 gennaio 2020 17:23
  • Ottimo suggerimento e fesso io per non esserci andato a guardare...

    sul server slave (SERVER2) ho trovato questo:

    Date,Source,Severity,Message
    01/09/2020 02:52:39,spid30s,Unknown,The recovery LSN (130010:14697648:1) was identified for the database with ID 5. This is an informational message only. No user action is required.
    01/09/2020 02:52:39,spid30s,Unknown,Always On Availability Groups connection with primary database established for secondary database 'PROBLEMATIC_DB' on the availability replica 'SERVER1\I02' with Replica ID: {cfc25fb6-a5df-4d5a-bee3-ae27af0e1b04}. This is an informational message only. No user action is required.
    01/09/2020 02:52:39,spid30s,Unknown,Always On Availability Groups transport has detected a missing log block for availability database "PROBLEMATIC_DB". LSN of last applied log block is (130010:14697640:0). Log scan will be restarted to fix the issue. This is an informational message only. No user action is required.
    01/09/2020 02:52:39,spid30s,Unknown,Error: 19432<c/> Severity: 16<c/> State: 0.
    01/09/2020 02:52:39,spid30s,Unknown,Always On Availability Groups transport has detected a missing log block for availability database "PROBLEMATIC_DB". LSN of last applied log block is (130010:14697640:0). Log scan will be restarted to fix the issue. This is an informational message only. No user action is required.
    01/09/2020 02:52:39,spid30s,Unknown,Error: 19432<c/> Severity: 16<c/> State: 0.
    01/09/2020 00:00:20,spid103s,Unknown,This instance of SQL Server has been using a process ID of 4672 since 17/12/2019 02:22:13 (local) 17/12/2019 01:22:13 (UTC). This is an informational message only; no user action is required.
    01/08/2020 23:50:14,spid69s,Unknown,The thread pool for Always On Availability Groups was unable to start a new worker thread because there are not enough available worker threads.  This may degrade Always On Availability Groups performance.  Use the "max worker threads" configuration option to increase number of allowable threads.
    01/08/2020 23:50:14,spid69s,Unknown,Error: 35217<c/> Severity: 16<c/> State: 1.

    Ovvero succede qualcosa alle 02:52 del giorno 9 ma ho il sospetto che possa dipendere dall'errore riportato all'evento precedente del giorno 8 alle 23:50 nel quale viene detto che non può essere creato un nuovo worker thread... Sul server primario ho più messaggi:

    Date,Source,Severity,Message
    01/09/2020 11:31:50,Server,Unknown,The Service Broker endpoint is in disabled or stopped state.
    01/09/2020 10:47:58,Backup,Unknown,Log was backed up. Database: PROBLEMATIC_DB<c/> creation date(time): 2019/12/06(14:25:13)<c/> first LSN: 130029:56:1<c/> last LSN: 130029:88:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'NUL'}). This is an informational message only. No user action is required.
    01/09/2020 10:47:57,Backup,Unknown,Log was backed up. Database: PROBLEMATIC_DB<c/> creation date(time): 2019/12/06(14:25:13)<c/> first LSN: 130011:7459096:1<c/> last LSN: 130029:56:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'NUL'}). This is an informational message only. No user action is required.
    01/09/2020 10:47:47,spid22s,Unknown,One or more recovery units belonging to database 'PROBLEMATIC_DB' failed to generate a checkpoint. This is typically caused by lack of system resources such as disk or memory<c/> or in some cases due to database corruption. Examine previous entries in the error log for more detailed information on this failure.
    01/09/2020 10:47:47,spid22s,Unknown,Error: 5901<c/> Severity: 16<c/> State: 1.
    01/09/2020 10:47:47,spid22s,Unknown,Could not write a checkpoint record in database PROBLEMATIC_DB because the log is out of space. Contact the database administrator to truncate the log or allocate more space to the database log files.
    01/09/2020 10:47:47,spid22s,Unknown,The transaction log for database 'PROBLEMATIC_DB' is full due to 'AVAILABILITY_REPLICA'.
    01/09/2020 10:47:47,spid22s,Unknown,Error: 9002<c/> Severity: 17<c/> State: 9.
    01/09/2020 10:47:47,Backup,Unknown,Log was backed up. Database: PROBLEMATIC_DB<c/> creation date(time): 2019/12/06(14:25:13)<c/> first LSN: 129893:208:1<c/> last LSN: 130011:7459096:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'NUL'}). This is an informational message only. No user action is required.
    01/09/2020 10:47:47,spid22s,Unknown,One or more recovery units belonging to database 'PROBLEMATIC_DB' failed to generate a checkpoint. This is typically caused by lack of system resources such as disk or memory<c/> or in some cases due to database corruption. Examine previous entries in the error log for more detailed information on this failure.
    01/09/2020 10:47:47,spid22s,Unknown,Error: 5901<c/> Severity: 16<c/> State: 1.
    01/09/2020 10:47:47,spid22s,Unknown,Could not write a checkpoint record in database PROBLEMATIC_DB because the log is out of space. Contact the database administrator to truncate the log or allocate more space to the database log files.
    01/09/2020 10:47:47,spid22s,Unknown,The transaction log for database 'PROBLEMATIC_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:47:47,spid22s,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:46:31,Backup,Unknown,BACKUP failed to complete the command BACKUP LOG PROBLEMATIC_DB. Check the backup application log for detailed messages.
    01/09/2020 10:46:31,Backup,Unknown,Error: 3041<c/> Severity: 16<c/> State: 1.
    01/09/2020 10:46:31,Backup,Unknown,BackupIoRequest::ReportIoError: write failure on backup device 'G:\Microsoft SQL Server\MSSQL14.I02\MSSQL\Backup\NULL'. Operating system error 112(There is not enough space on the disk.).
    01/09/2020 10:46:31,Backup,Unknown,Error: 18210<c/> Severity: 16<c/> State: 1.
    01/09/2020 10:45:32,spid64,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:45:32,spid64,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:44:00,spid92,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:44:00,spid92,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:43:51,spid75,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:43:51,spid75,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:43:44,spid75,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:43:44,spid75,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:36:17,spid97,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:36:17,spid97,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:36:05,spid75,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:36:05,spid75,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:35:24,spid75,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:35:24,spid75,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:35:21,spid64,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:35:21,spid64,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:35:00,spid64,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:35:00,spid64,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:34:18,spid75,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:34:18,spid75,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:34:14,spid75,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:34:14,spid75,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:30:33,spid92,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:30:33,spid92,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:20:14,spid55,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:20:14,spid55,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:18:24,spid63,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:18:24,spid63,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:17:05,spid97,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:17:05,spid97,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:12:05,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:12:05,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:10:55,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:10:55,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 10:02:59,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 10:02:59,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:47:26,spid92,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:47:26,spid92,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:47:03,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:47:03,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:43:43,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:43:43,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:43:28,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:43:28,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:43:27,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:43:27,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:43:27,spid91,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:43:27,spid91,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:42:30,spid73,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:42:30,spid73,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:42:11,spid74,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:42:11,spid74,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:42:05,spid73,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:42:05,spid73,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:41:23,spid74,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:41:23,spid74,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:41:05,spid74,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:41:05,spid74,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:39:46,spid74,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:39:46,spid74,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:37:22,spid74,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:37:22,spid74,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:24:49,spid52,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:24:49,spid52,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 09:24:39,spid52,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 09:24:39,spid52,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:44:22,spid82,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:44:22,spid82,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:43:00,spid85,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:43:00,spid85,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:42:18,spid85,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:42:18,spid85,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:38:58,spid83,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:38:58,spid83,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:23:53,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:23:53,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:21:14,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:21:14,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:21:04,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:21:04,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:20:21,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:20:21,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:20:20,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:20:20,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:20:20,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:20:20,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:16:01,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:16:01,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:15:21,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:15:21,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:13:44,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:13:44,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:13:23,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:13:23,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:13:09,spid56,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:13:09,spid56,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:07:20,spid83,Unknown,The transaction log for database 'OTHER_DB' is full due to 'LOG_BACKUP'.
    01/09/2020 08:07:20,spid83,Unknown,Error: 9002<c/> Severity: 17<c/> State: 2.
    01/09/2020 08:07:20,spid83,Unknown,G:\Microsoft SQL Server\MSSQL14.I02\MSSQL\DATA\OTHER_DB_log.ldf: Operating system error 112(There is not enough space on the disk.) encountered.
    01/09/2020 08:07:20,spid83,Unknown,Error: 17053<c/> Severity: 16<c/> State: 1.
    01/09/2020 04:22:59,spid72s,Unknown,G:\Microsoft SQL Server\MSSQL14.I02\MSSQL\DATA\PROBLEMATIC_DB_log.ldf: Operating system error 112(There is not enough space on the disk.) encountered.
    01/09/2020 04:22:59,spid72s,Unknown,Error: 17053<c/> Severity: 16<c/> State: 1.
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncState: B2CB6886-AD8C-441B-8860-B802D97B1F94:4
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:4
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:4
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid89s,Unknown,Always On Availability Groups connection with secondary database established for primary database 'PROBLEMATIC_DB' on the availability replica 'SERVER2\I02' with Replica ID: {b2cb6886-ad8c-441b-8860-b802d97b1f94}. This is an informational message only. No user action is required.
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid89s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid91s,Unknown,DbMgrPartnerCommitPolicy::SetSyncState: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid91s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid91s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:1
    01/09/2020 02:52:39,spid91s,Unknown,DbMgrPartnerCommitPolicy::SetSyncAndRecoveryPoint: B2CB6886-AD8C-441B-8860-B802D97B1F94:4
    01/09/2020 00:00:52,spid62s,Unknown,This instance of SQL Server has been using a process ID of 4696 since 17/12/2019 02:46:41 (local) 17/12/2019 01:46:41 (UTC). This is an informational message only; no user action is required.

    sempre alle 02:52 del giorno 9 succede qualcosa relativamente alla replica AlwaysOn e alle 04:22 il disco si è riempito.

    Ciao,



    Dario Palermo

    sabato 11 gennaio 2020 21:57
  • Ciao Dario,

    grazie per aver riportato il feedback qui. In aggiunta al suggerimento di Massimo, ti segnalo questo articolo della KB:

    Error 9002. The transaction log for database is full due to AVAILABILITY_REPLICA

    Una curiosità, quando il transaction log è in questo stato, se esegui la query seguente, che descrizione viene riportata nella colonna log_reuse_wait_desc ?

    SELECT name, log_reuse_wait, log_reuse_wait_desc, * FROM sys.databases

    Ciao!


    Sergio Govoni

    Microsoft Data Platform MVP | MVP Profile | English Blog | Twitter | LinkedIn


    domenica 12 gennaio 2020 14:40
    Moderatore
  • scusate il ritardo nella risposta ma il problema si presenta abbastanza di rado. In questo momento è riaccaduto.

    di seguito il risultato della query indicatami (ho notato che un database - ma non quello "problematico" - presenta uno stato diverso tra i due server)

    SERVER MASTER SERVER SLAVE
    aaaAUTOTelemaco_Test 2 LOG_BACKUP aaaAUTOTelemaco_Test 2 LOG_BACKUP
    aaaAUTOPlus 0 NOTHING aaaAUTOPlus 0 NOTHING
    aaaAUTOPlus_Test 2 LOG_BACKUP aaaAUTOPlus_Test 2 LOG_BACKUP
    aaaAUTORendiconto 0 NOTHING aaaAUTORendiconto 0 NOTHING
    aaaAUTORendiconto_Test 0 NOTHING aaaAUTORendiconto_Test 0 NOTHING
    aaaAUTOSql 2 LOG_BACKUP aaaAUTOSql 2 LOG_BACKUP
    aaaAUTOSql_Test 0 NOTHING aaaAUTOSql_Test 0 NOTHING
    aaaAUTOTelemaco 2 LOG_BACKUP aaaAUTOTelemaco 2 LOG_BACKUP
    aaaAUTOTelemacoDocumenti 2 LOG_BACKUP aaaAUTOTelemacoDocumenti 2 LOG_BACKUP
    aaaPlus 0 NOTHING aaaPlus 0 NOTHING
    aaaPlusTEST 0 NOTHING aaaPlusTEST 0 NOTHING
    aaaRendiconto 0 NOTHING aaaSqlTEST 0 NOTHING
    aaaRendicontoTEST 2 LOG_BACKUP aaaTelemaco 2 LOG_BACKUP
    aaaSql 2 LOG_BACKUP aaaRendiconto 0 NOTHING
    aaaSqlTEST 0 NOTHING aaaRendicontoTEST 2 LOG_BACKUP
    aaaTelemaco 2 LOG_BACKUP aaaSql 2 LOG_BACKUP
    aaaTelemacoTEST 2 LOG_BACKUP aaaTelemacoTEST 2 LOG_BACKUP

    ciao


    Dario Palermo

    giovedì 16 gennaio 2020 15:08
  • Ciao Dario,

    per lo stato diverso visualizzato nella colonna log_reuse_wait_desc, ho controllato la tabella e.. a meno che non abbia preso io un abbaglio, lo stato è uguale per tutti i DB. Fino al database aaaPlusTEST compreso, le righe sono allineate allo stesso DB, ma scorrendo avanti la stessa riga riporta DB diversi tra master e slave..

    Il T-Log cresciuti a dismisura sono relativi a database con log_reuse_wait_desc in stato LOG_BACKUP?

    Quando è successo il server slave aveva problemi di performance o era in uso stato di bottleneck?

    Se dovesse succedere di nuovo, mandaci anche il risultato di questa query:

    SELECT
     ag.name AS [availability_group_name]
     ,d.name AS [database_name]
     ,ar.replica_server_name AS [replica_instance_name]
     ,drs.truncation_lsn
     ,drs.log_send_queue_size
     ,drs.redo_queue_size
    FROM
      sys.availability_groups ag
    INNER JOIN
      sys.availability_replicas ar ON ar.group_id = ag.group_id
    INNER JOIN
      sys.dm_hadr_database_replica_states drs ON drs.replica_id = ar.replica_id
    INNER JOIN
      sys.databases d ON d.database_id = drs.database_id
    WHERE
      drs.is_local=0
    ORDER BY
      ag.name ASC
      ,d.name ASC
      ,drs.truncation_lsn ASC
      ,ar.replica_server_name ASC;
    GO

    In questo articolo ci sono informazioni interessanti: https://support.microsoft.com/en-us/help/2922898/error-9002-the-transaction-log-for-database-full-due-to-availability

    Ciao!


    Sergio Govoni

    Microsoft Data Platform MVP | MVP Profile | English Blog | Twitter | LinkedIn


    sabato 25 gennaio 2020 12:22
    Moderatore
  • Ciao Sergio,

    scusami è stato un problema di ordinamento delle righe nella tabella che ho approntato. Il database che crea il problema è sempre lo stesso (su questa istanza, ed è un altro - ma anche in quel caso sempre lo stesso - sull'altra istanza: 

    aaaAUTOTelemaco_Test 2 LOG_BACKUP

    non è l'unico in questo stato e non mi spiego perchè sia sempre e solo lui a causare il problema. L'ho anche escluso e riaggiunto al gruppo di replica ma nulla da fare, il problema di tanto in tanto (ovvero a distanza di giorni) si ripresenta.

    Non mi sembra che i server abbiano avuto problemi di performance... quali indicatori ti interessano in particolare?

    PS

    tengo pronta la query per la prossima volta che il problema si ripresenterà, grazie

    Ciao,


    Dario Palermo

    sabato 25 gennaio 2020 14:25

  • Non mi sembra che i server abbiano avuto problemi di performance... quali indicatori ti interessano in particolare?

    Ciao Dario,

    controllerei gli indicatori descritti qui: Troubleshoot: Availability group exceeded RPO.

    Il T-Log del database aaaAUTOTelemaco_Test continua a crescere e lo spazio allocato non viene rilasciato perchè si attende un backup del log (LOG_BACKUP nella colonna log_reuse_wait_desc).

    Questo stato preceduto dal messaggio:

    "The thread pool for Always On Availability Groups was unable to start a new worker thread because there are not enough available worker threads.  This may degrade Always On Availability Groups performance.  Use the "max worker threads" configuration option to increase number of allowable threads"

    E successivamente dall'errore:

    "The transaction log for database 'PROBLEMATIC_DB' is full due to 'AVAILABILITY_REPLICA'"

    Mi portano a pensare che il server primario non riesca a completare la sincronizzazione sul secondario, da qui l'impossibilità di fare backup del log, da qui la crescita.

    Il perchè sempre sullo stesso DB si potrebbe spiegare se quel DB fosse il più utilizzato dell'istanza.

    Qui trovi informazioni aggiuntive:

    https://docs.microsoft.com/en-us/previous-versions/sql/sql-server-2008-r2/ms345414(v=sql.105)?redirectedfrom=MSDN

    https://techcommunity.microsoft.com/t5/sql-server-support/alwayson-hadron-learning-series-lock-redo-blocked-redo-worker/ba-p/317628

    Ciao e.. buona domenica! :)


    Sergio Govoni

    Microsoft Data Platform MVP | MVP Profile | English Blog | Twitter | LinkedIn



    domenica 26 gennaio 2020 11:24
    Moderatore
  • In realtà i due DB che creano problemi sono utilizzati pochissimo (quello che termina in _test) o per niente affatto (DBSTART2).

    In realtà pensavo di disabilitare la replica di questi DB per un mesetto (tanto uno è di test e lo recupero dalla produzione e l'altro è di sola lettura e lo recupero da un backup) per capire se, tolti questi due, il problema inizia a presentarsi su altri database.

    Ciao,


    Dario Palermo

    domenica 26 gennaio 2020 12:10
  • In realtà i due DB che creano problemi sono utilizzati pochissimo (quello che termina in _test) o per niente affatto (DBSTART2).

    Ciao Dario,

    eh infatti ricordavo avevi detto fossero poco utilizzati.. la situazione quindi è ancora più strana.

    Se puoi disabilitare la replica di questi due per un po' di tempo possiamo procedere così.. però non avremo altre informazioni sul caso..

    Ciao


    Sergio Govoni

    Microsoft Data Platform MVP | MVP Profile | English Blog | Twitter | LinkedIn

    domenica 26 gennaio 2020 12:17
    Moderatore
  • L'assenza di informazioni sarebbe essa stessa una informazione utile: se il problema non si ripresenta allora è probabilmente legato ai due DB in particolare (magari a qualche situazione strana che si è venuta a creare quando sono stati inseriti nei gruppi AlwaysOn e che eventualmente la rimozione e riaggiunta non risolve?).

    In realtà io scommetto che il problema si ripresenterà su altri DB... se non lo fa intendo creare un altro paio di DB da inserire in AlwaysOn per verificare se si tratta di un problema di esaurimento risorse.

    ciao,


    Dario Palermo

    domenica 26 gennaio 2020 13:30
  • Ciao Dario,

    OK, aggiorniamoci tra un po' di tempo..

    A presto!


    Sergio Govoni

    Microsoft Data Platform MVP | MVP Profile | English Blog | Twitter | LinkedIn

    domenica 26 gennaio 2020 17:09
    Moderatore
  • Nulla da fare, il problema si è ripresentato anche senza che il db fosse in alwayson...

    mi sembra che l'unico ad accedervi sia l'agente di arcserve backup, possibile che crei lui il problema? come posso capire cosa sta finendo nel log che lo fa diventare così enorme?

    PS

    sto tentando il solito shrink (dopo un backup log to nul) e mi esce questo:

    Msg 9002, Level 17, State 9, Line 4
    The transaction log for database 'XXXAUTOTelemaco_Test' is full due to 'AVAILABILITY_REPLICA'.

    però il db non è nel gruppo di alwayson!

    ciao,


    Dario Palermo


    sabato 1 febbraio 2020 09:46
  • Ciao Dario,

    per leggere il contenuto del transaction log ci sono due funzioni non documentate: fn_dblog e fn_dump_dblog.

    In questi articoli trovi gli esempi di utilizzo:

    https://solutioncenter.apexsql.com/it/leggere-il-log-delle-transazioni-di-un-database-di-sql-server/ 

    https://www.mssqltips.com/sqlservertip/3076/how-to-read-the-sql-server-database-transaction-log/

    Un controllo sulle impostazioni di Arcserve lo farei!

    Domanda banale: su questo database chi lancia il comando BACKUP LOG.. se è Arcserve controllerei come viene fatta questa operazione..

    Una considerazione sul BACKUP LOG TO NUL: Per il SO, NUL è un dispositivo trattato come file, un "file" speciale che elimina tutti i dati che vi sono scritti. I Log record verranno comunque conservati dopo un backup TO NUL..

    Ciao


    Sergio Govoni

    Microsoft Data Platform MVP | MVP Profile | English Blog | Twitter | LinkedIn

    sabato 1 febbraio 2020 16:53
    Moderatore
  • in realtà il log si è riempito alle 16 e rotti di ieri e, da quanto ho capito, il backup era stato fatto alle 20 circa del giorno precedente... devo vedere con chi gestisce il backup che cosa gli risulta dal suo lato.

    Io lancio il backup manuale del log a nul e poi faccio shrink del file (in geenre sono necessari almeno due "cicli" per vedere lo spazio su disco ridotto).

    Ciao,


    Dario Palermo

    sabato 1 febbraio 2020 17:13