GET 24/7 LIVE HELP NOW

Announcement

Announcement Module
Collapse
No announcement yet.

innobackupex apply-log error for fullbackup

Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • innobackupex apply-log error for fullbackup

    I am taking a fullbackup using

    My Data directory are on local directory and I am taking backup on NFS mount point.


    innobackupex --slave-info --safe-slave-backup /gwire_dw/extradbbackuptest/

    please note : /gwire_dw/ is a netapp mount point

    backup is successful.

    next when I go to prepare the fullbackup

    using

    innobackupex --defaults-file=/etc/my.cnf --apply-log --use-memory=8G /gwire_dw/extradbbackuptest/2013-12-30_16-39-55

    it fails

    here is the prepare log

    InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
    and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

    This software is published under
    the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

    IMPORTANT: Please check that the apply-log run completes successfully.
    At the end of a successful apply-log run innobackupex
    prints "completed OK!".



    131230 21:16:10 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/etc/my.cnf" --defaults-group="mysqld" --prepare --target-dir=/gwire_dw/extradbbackuptest/2013-12-30_16-39-55 --use-memory=8G --tmpdir=/tmp

    xtrabackup_55 version 2.1.5 for Percona Server 5.5.31 Linux (x86_64) (revision id: 680)
    xtrabackup: cd to /gwire_dw/extradbbackuptest/2013-12-30_16-39-55
    xtrabackup: This target seems to be not prepared yet.
    xtrabackup: xtrabackup_logfile detected: size=3633463296, start_lsn=(1417494366104)
    xtrabackup: using the following InnoDB configuration for recovery:
    xtrabackup: innodb_data_home_dir = ./
    xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
    xtrabackup: innodb_log_group_home_dir = ./
    xtrabackup: innodb_log_files_in_group = 1
    xtrabackup: innodb_log_file_size = 3633463296
    xtrabackup: using the following InnoDB configuration for recovery:
    xtrabackup: innodb_data_home_dir = ./
    xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
    xtrabackup: innodb_log_group_home_dir = ./
    xtrabackup: innodb_log_files_in_group = 1
    xtrabackup: innodb_log_file_size = 3633463296
    xtrabackup: Starting InnoDB instance for recovery.
    xtrabackup: Using 8589934592 bytes for buffer pool (set by --use-memory parameter)
    131230 21:16:17 InnoDB: The InnoDB memory heap is disabled
    131230 21:16:17 InnoDB: Mutexes and rw_locks use GCC atomic builtins
    131230 21:16:17 InnoDB: Compressed tables use zlib 1.2.3
    131230 21:16:17 InnoDB: Initializing buffer pool, size = 8.0G
    131230 21:16:17 InnoDB: Completed initialization of buffer pool
    131230 21:16:17 InnoDB: highest supported file format is Barracuda.
    InnoDB: Log scan progressed past the checkpoint lsn 1417494366104
    131230 21:16:17 InnoDB: Database was not shut down normally!
    InnoDB: Starting crash recovery.
    InnoDB: Reading tablespace information from the .ibd files...
    InnoDB: Doing recovery: scanned up to log sequence number 1417499608576 (0 %)
    ...
    InnoDB: Doing recovery: scanned up to log sequence number 1420723979776 (99 %)
    InnoDB: Doing recovery: scanned up to log sequence number 1420724108086 (99 %)
    131230 21:17:30 InnoDB: Starting an apply batch of log records to the database...
    InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 131230 21:18:55 InnoDB: Assertion failure in thread 140345562953472 in file rem0rec.c line 569
    InnoDB: We intentionally generate a memory trap.
    InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
    InnoDB: If you get repeated assertion failures or crashes, even
    InnoDB: immediately after the mysqld startup, there may be
    InnoDB: corruption in the InnoDB tablespace. Please refer to
    InnoDB: http://dev.mysql.com/doc/refman/5.5/...-recovery.html
    InnoDB: about forcing recovery.
    innobackupex: Error:
    innobackupex: ibbackup failed at /usr/bin/innobackupex line 2517.

    I checked these 2 lines from the log

    xtrabackup: cd to /gwire_dw/extradbbackuptest/2013-12-30_16-39-55
    xtrabackup: This target seems to be not prepared yet.

    but this directory exists.

    Please help I am trying this for last 2-3 days and its not working .

  • #2
    My.cnf looks like this

    [mysqld]
    log-bin = /var/lib/mysqllogs/bin.log
    log-bin-index = /var/lib/mysqllogs/log-bin.index
    performance_schema
    datadir=/var/lib/mysql
    relay-log=/var/lib/mysqllogs/relay.log
    relay-log-index=/var/lib/mysqllogs/relay-log
    user=mysql
    symbolic-links=0
    max_connections=500
    skip-slave-start
    max_allowed_packet=100M
    innodb_file_format=Barracuda
    innodb_flush_log_at_trx_commit = 2
    innodb-log-buffer-size=16M
    innodb_buffer_pool_size=10G
    innodb_log_file_size=64M
    innodb_file_per_table
    innodb_flush_method=O_DIRECT
    table_cache = 3000
    skip-name-resolve
    thread_cache_size =150
    innodb_buffer_pool_instances=10

    Comment


    • #3
      Can you please try to prepare backup without --defaults-file=/etc/my.cnf option and check if it works.
      For further details check highlighted "Note" section in documentation here http://www.percona.com/doc/percona-x...ckup%3aprepare

      Comment


      • #4
        I tried running prepare without --defaults-file=/etc/my.cnf and its same error

        Assertion failure in thread 140336965527296 in file rem0rec.c line 569

        Comment


        • #5
          Please share source MySQL version from where you took the backup and version of xtrabackup you are trying with. Also, try with latest xtrabackup version and post full backup log in case if error persists.

          Comment


          • #6
            so it failed again though this time with another error

            extrabacup version percona-xtrabackup-2.1.6-702.rhel6.x86_64
            MySQL version 5.5.34-log

            Data Directory Size 409 GB

            Tables are compressed .

            Backup taken by running this command

            innobackupex --slave-info --safe-slave-backup /gwire_dw/extradbbackuptest/ 2>&1 | tee /tmp/backup3rdjan2004.txt



            backup log


            InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
            and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

            This software is published under
            the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

            Get the latest version of Percona XtraBackup, documentation, and help resources:
            http://www.percona.com/xb/p

            140102 20:40:55 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup' as 'bkpuser' (using password: YES).
            140102 20:40:55 innobackupex: Connected to MySQL server
            140102 20:40:55 innobackupex: Executing a version check against the server...

            # A software update is available:
            # * The current version for MySQL Community Server (GPL) is 5.5.35.

            140102 20:40:56 innobackupex: Done.
            IMPORTANT: Please check that the backup run completes successfully.
            At the end of a successful backup run innobackupex
            prints "completed OK!".

            innobackupex: Using mysql server version 5.5.34-log

            innobackupex: Created backup directory /gwire_dw/extradbbackuptest/2014-01-02_20-40-57

            140102 20:40:57 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/gwire_dw/extradbbackuptest/2014-01-02_20-40-57 --tmpdir=/tmp
            innobackupex: Waiting for ibbackup (pid=7231) to suspend
            innobackupex: Suspend file '/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/xtrabackup_suspended_2'

            xtrabackup_55 version 2.1.6 for Percona Server 5.5.31 Linux (x86_64) (revision id: 702)
            xtrabackup: uses posix_fadvise().
            xtrabackup: cd to /gwire_dw/mysql_app278/mysql
            xtrabackup: using the following InnoDB configuration:
            xtrabackup: innodb_data_home_dir = ./
            xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
            xtrabackup: innodb_log_group_home_dir = ./
            xtrabackup: innodb_log_files_in_group = 2
            xtrabackup: innodb_log_file_size = 67108864
            xtrabackup: using O_DIRECT
            >> log scanned up to (1464649810058)
            140102 20:41:01 InnoDB: Warning: allocated tablespace 44, old maximum was 9
            [01] Copying ./ibdata1 to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/ibdata1
            [01] xtrabackup: Page 64 is a doublewrite buffer page, skipping.
            ...
            [01] xtrabackup: Page 188 is a doublewrite buffer page, skipping.
            >> log scanned up to (1464649973184)

            >> log scanned up to (1464661518012)
            [01] ...done
            [01] Copying ./test/pankaj.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/test/pankaj.ibd
            [01] ...done
            [01] Copying ./hydra/url_count.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/hydra/url_count.ibd
            [01] ...done
            [01] Copying ./hydra/hydra_es_index.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/hydra/hydra_es_index.ibd
            [01] ...done
            [01] ./hydra/hydra_content.ibd is compressed with page size = 8192 bytes
            [01] Copying ./hydra/hydra_content.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/hydra/hydra_content.ibd
            >> log scanned up to (1464661839410)
            .....

            >> log scanned up to (1467316471704)
            [01] ...done
            [01] Copying ./monitoring/heartbeat.ibd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57/monitoring/heartbeat.ibd
            [01] ...done
            >> log scanned up to (1467316474619)
            xtrabackup: Creating suspend file '/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/xtrabackup_suspended_2' with pid '7231'
            >> log scanned up to (1467316475067)

            140103 02:01:21 innobackupex: Continuing after ibbackup has suspended
            innobackupex:: Slave open temp tables: 0
            140103 02:01:21 innobackupex: Starting to lock all tables...
            140103 02:01:21 innobackupex: All tables locked and flushed to disk

            140103 02:01:21 innobackupex: Starting to backup non-InnoDB tables and files
            innobackupex: in subdirectories of '/gwire_dw/mysql_app278/mysql'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/test/pankaj.frm'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/hydra/hydra_content.frm'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/hydra/hydra_es_index.frm'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/hydra/url_count.frm'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/hydra/hydra_hash.frm'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/hydra/db.opt'
            innobackupex: Backing up files '/gwire_dw/mysql_app278/mysql/mysql/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM ,CSV,opt,par}' (75 files)
            >> log scanned up to (1467316475720)
            >> log scanned up to (1467316476598)
            >> log scanned up to (1467316476598)
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/monitoring/heartbeat.frm'
            innobackupex: Backing up file '/gwire_dw/mysql_app278/mysql/monitoring/db.opt'
            innobackupex: Backing up files '/gwire_dw/mysql_app278/mysql/performance_schema/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM ,CSV,opt,par}' (18 files)
            >> log scanned up to (1467316479669)
            140103 02:01:26 innobackupex: Finished backing up non-InnoDB tables and files

            140103 02:01:26 innobackupex: Waiting for log copying to finish

            xtrabackup: The latest check point (for incremental): '1467297323880'
            xtrabackup: Stopping log copying thread.
            .>> log scanned up to (1467316479669)

            xtrabackup: Creating suspend file '/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/xtrabackup_log_copied' with pid '7231'
            xtrabackup: Transaction log of lsn (1464554168682) to (1467316479669) was copied.
            140103 02:01:27 innobackupex: All tables unlocked
            innobackupex:: Starting slave SQL thread

            innobackupex: Backup created in directory '/gwire_dw/extradbbackuptest/2014-01-02_20-40-57'
            innobackupex: MySQL binlog position: filename 'bin.000006', position 107
            innobackupex: MySQL slave binlog position: master host '10.0.7.79', filename 'bin.000186', position 117927779
            140103 02:01:27 innobackupex: Connection to database server closed
            140103 02:01:27 innobackupex: completed OK!

            so backup was successful

            prepare log is ...

            Comment


            • #7
              now Preparing backup

              command

              innobackupex --apply-log --use-memory=8G /gwire_dw/extradbbackuptest/2014-01-02_20-40-57 2>&1 | tee /tmp/prepare3rdjan2004.txt


              InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
              and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

              This software is published under
              the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

              Get the latest version of Percona XtraBackup, documentation, and help resources:
              http://www.percona.com/xb/p

              IMPORTANT: Please check that the apply-log run completes successfully.
              At the end of a successful apply-log run innobackupex
              prints "completed OK!".



              140103 02:33:56 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/gwire_dw/extradbbackuptest/2014-01-02_20-40-57/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/gwire_dw/extradbbackuptest/2014-01-02_20-40-57 --use-memory=8G --tmpdir=/tmp

              xtrabackup_55 version 2.1.6 for Percona Server 5.5.31 Linux (x86_64) (revision id: 702)
              xtrabackup: cd to /gwire_dw/extradbbackuptest/2014-01-02_20-40-57
              xtrabackup: This target seems to be not prepared yet.
              140103 2:33:56 InnoDB: Operating system error number 2 in a file operation.
              InnoDB: The error means the system cannot find the path specified.
              xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to find.
              xtrabackup: 'ib_logfile0' seems to be 'xtrabackup_logfile'. will retry.
              xtrabackup: xtrabackup_logfile detected: size=3933044736, start_lsn=(1464554168682)
              xtrabackup: using the following InnoDB configuration for recovery:
              xtrabackup: innodb_data_home_dir = ./
              xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
              xtrabackup: innodb_log_group_home_dir = ./
              xtrabackup: innodb_log_files_in_group = 1
              xtrabackup: innodb_log_file_size = 3933044736
              xtrabackup: using the following InnoDB configuration for recovery:
              xtrabackup: innodb_data_home_dir = ./
              xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
              xtrabackup: innodb_log_group_home_dir = ./
              xtrabackup: innodb_log_files_in_group = 1
              xtrabackup: innodb_log_file_size = 3933044736
              xtrabackup: Starting InnoDB instance for recovery.
              xtrabackup: Using 8589934592 bytes for buffer pool (set by --use-memory parameter)
              140103 2:34:03 InnoDB: The InnoDB memory heap is disabled
              140103 2:34:03 InnoDB: Mutexes and rw_locks use GCC atomic builtins
              140103 2:34:03 InnoDB: Compressed tables use zlib 1.2.3
              140103 2:34:03 InnoDB: Initializing buffer pool, size = 8.0G
              140103 2:34:03 InnoDB: Completed initialization of buffer pool
              140103 2:34:03 InnoDB: highest supported file format is Barracuda.
              InnoDB: Log scan progressed past the checkpoint lsn 1464554168682
              140103 2:34:04 InnoDB: Database was not shut down normally!
              InnoDB: Starting crash recovery.
              InnoDB: Reading tablespace information from the .ibd files...
              InnoDB: Doing recovery: scanned up to log sequence number 1464559411200 (0 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1464564654080 (0 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1464569896960 (0 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1464575139840 (0 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1464580382720 (0 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1464585625600 (0 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1464590868480 (1 %)
              InnoDB: Doing recovery: scanned up to log sequence number 1467316479669 (79 %)
              140103 2:35:07 InnoDB: Starting an apply batch of log records to the database...
              InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 InnoDB: Probable data corruption on page 50419077
              InnoDB: Original record (compact record)
              InnoDB: on that page.
              InnoDB: Cannot find the dir slot for record (compact record)
              InnoDB: on that page!
              140103 2:35:40 InnoDB: Page dump in ascii and hex (16384 bytes):
              len 16384; hex 00000000030123733383032636536000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000000000000000 00000000000000000000000000000000000000007000630000 01553c72e293; asc U U U<r E ; ! b 7 + infimum supremum@e o _ + B B BLhttp://www.yourtango.com/2013175840/did-seth-macfarlane-go-too-far7f167d57fe2996111c9e05b5ddb7707d P engaged, married, oscars 2013, oscars, seth macfarlane, family guys, sexism, jokes, weight, boobs, single, love buzz, life stylewere his jokes about women sexist or funny? {"lookswelove":0.12883829496532057}]}]53b4519476cb03b95d942a028b2e2831aac39687ec1097a70a 4b966c0b68afeb@ T ( B ;v= V http://www.morphthing.com/setPoints/...5de9942d66ff02 P Q; go Q; gofb45806ba70b2a85d4193080483077e67c4aab7a5dcaee8f cfafa3b273802ce6 p c U<r ;
              InnoDB: End of page dump
              140103 2:35:40 InnoDB: Page checksum 4130229248 (32bit_calc: 2497019130), prior-to-4.0.14-form checksum 3591539239
              InnoDB: stored checksum 0, prior-to-4.0.14-form stored checksum 341
              InnoDB: Page lsn 341 1014162067, low 4 bytes of lsn at page end 1014162067
              InnoDB: Page number (if stored to page already) 50419077,
              InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 25
              InnoDB: Page may be an update undo log page
              InnoDB: Page may be an index page where index id is 55
              140103 2:35:40 InnoDB: Assertion failure in thread 139802270525184 in file page0page.c line 153
              InnoDB: We intentionally generate a memory trap.
              InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
              InnoDB: If you get repeated assertion failures or crashes, even
              InnoDB: immediately after the mysqld startup, there may be
              InnoDB: corruption in the InnoDB tablespace. Please refer to
              InnoDB: http://dev.mysql.com/doc/refman/5.5/...-recovery.html
              InnoDB: about forcing recovery.
              innobackupex: Error:
              innobackupex: ibbackup failed at /usr/bin/innobackupex line 2569.

              I am not sure what's happening here , my.cnf is same what was mentioned earlier . please help.

              Comment


              • #8
                Hi Pankaj Joshi

                The root cause of problem could be data corruption.
                Let me help you to check if it's so.

                - create file "ibd_checksum.sh" with source code:

                #!/bin/bash
                for i in $(ls /var/lib/mysql/*/*.ibd)
                do
                innochecksum -v $i
                done

                - set permissions: chmod +x ibd_checksum.sh
                - run it and save it's log: sudo ./ibdscript.sh > idb_checksum.log

                And attach here idb_checksum.log or send us the output of "sudo ./ibdscript.sh" command

                I would also ask you to run this command in mysql:

                select
                i.index_id, i.name, t.table_id, t.schema, t.name
                from
                innodb_sys_indexes i
                left join innodb_sys_tables t on i.table_id = t.table_id
                where index_id=55

                ---

                If you'll find that you have a corrupted table then you can try innodb_force_recovery.
                http://dev.mysql.com/doc/refman/5.5/...-recovery.html

                Add this:
                innodb_force_recovery = 1
                (you can start from 1 and change it to 6 if needed; this is well described in the URL below)

                To your MySQL config (my.cnf) and restart MySQL.
                Check MySQL error log for details.

                If the culprit is data corruption then after you'll solve it you should be able to backup your data.
                Please check and let us to know.
                Last edited by mixa; 01-07-2014, 10:39 AM.

                Comment


                • #9
                  Hello Mixa

                  thanks for looking into this, I am running the script now and will share the findings .

                  I am using MySQL version 5.5.34-log so the query which you mentioned is not able to run .

                  select
                  i.index_id, i.name, t.table_id, t.schema, t.name
                  from
                  innodb_sys_indexes i
                  left join innodb_sys_tables t on i.table_id = t.table_id
                  where index_id=55

                  any alternate query which could get the expected results from above mentioned query.

                  Comment


                  • #10
                    Can you please try this one?
                    My mistake I didn't add database name here...
                    Or run "use mysql;" command before running te previous one.
                    The point here - it gets data from tables from database with name "mysql"

                    select
                    i.index_id, i.name, t.table_id, t.schema, t.name
                    from
                    mysql.innodb_sys_indexes i
                    left join mysql.innodb_sys_tables t on i.table_id = t.table_id
                    where index_id=55

                    Comment


                    • #11
                      select
                      i.index_id, i.name, t.table_id, t.schema, t.name
                      from
                      mysql.innodb_sys_indexes i
                      left join mysql.innodb_sys_tables t on i.table_id = t.table_id
                      where index_id=55

                      it gives me this error

                      Table 'mysql.innodb_sys_indexes' doesn't exist .

                      Please note I am using MySQL version 5.5.34-log

                      I also ran the script which you sent .

                      this is the final output

                      ./ibd_checksum.sh &gt; idb_checksum.log
                      page 0 invalid (fails log sequence number check)

                      please note we are using compression for tables .


                      I am attaching the complete log as well.

                      Comment


                      • #12
                        Hello mixa/mirfan

                        can you please look into this and let me know if I can provide any information to be able to fix this issue . thanks in advance.

                        Comment


                        • #13
                          Hello Percona Team.

                          I upgraded MySQL 5.5.34 to 5.6.11 and was able to take the backup and prepare it successfully with xtrabackup_56 version 2.1.5 . Thank you for all your support really appreciate it.

                          Comment


                          • #14
                            Hi Pankaj,
                            Glad that it worked for you.
                            Can you please try to restore backup on some test environment?
                            Just to be sure that it works and not corrupted or something...

                            Comment


                            • #15
                              Hello Mixa,

                              Aplogies for delayed response , I restored backup on a server by manually copying the backup directory to another server and it worked. infact I set a new slave by taking backup of existing slave .

                              Thanks
                              Pankaj

                              Comment

                              Working...
                              X