[MDEV-27919] mariabackup --log-copy-interval is measured in milliseconds in 10.5 and in microseconds in 10.6 - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.6.7
Fix Version/s: 10.6.8, 10.7.4, 10.8.3, 10.9.1
Component/s: mariabackup
Labels:
None

Description

Hi, all MariaBackup developers.

We have two MariaDB clusters, which both version 10.0.x

And recently upgraded from 10.0.x to 10.6.2
But I found that the log ">> log scanned up to (...)" print too fast, overwhelming the stdout/stderr. (the log file size is occupied by several gigabytes)

But as I tested, when I upgraded from 10.0.x to 10.5.x, the log ">> log scanned up to (...)" is not so overwhelming. (the log file size is occupied by several megabytes)

FYI, Recovered from the same database backup.

It sounds like a bug in mariabackup, since the --log-copy-interval (default is 1000ms) can't control the log output frequency.

# 10.5 MariaBackup

# One log per second

[00] 2022-02-14 17:50:25 >> log scanned up to (46200984432003)

[00] 2022-02-14 17:50:26 >> log scanned up to (46200984454330)

[00] 2022-02-14 17:50:27 >> log scanned up to (46200984469322)

[00] 2022-02-14 17:50:28 >> log scanned up to (46200984491853)

[00] 2022-02-14 17:50:29 >> log scanned up to (46200984529292)

[00] 2022-02-14 17:50:30 >> log scanned up to (46200984561329)

# 10.6 MariaBackup

# --log-copy-interval=1000 is not working for 10.6

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221905582)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221906153)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221906805)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221906805)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221906805)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221907586)

[00] 2022-02-22 17:11:48 >> log scanned up to (46276221908255)

Attachments

Issue Links

relates to

MDEV-25765 Mariabackup reduced verbosity option for log output.

Closed

Activity

Ascending order - Click to sort in descending order

Harvey Cooper created issue - 2022-02-23 02:59

Harvey Cooper made changes - 2022-02-25 01:38

Field	Original Value	New Value
Link		This issue is part of ~~MDEV-27931~~ [ ~~MDEV-27931~~ ]

Marko Mäkelä made changes - 2022-03-25 15:25

Link

This issue is part of ~~MDEV-27931~~ [ ~~MDEV-27931~~ ]

Marko Mäkelä added a comment - 2022-03-25 15:29

Our regression tests (mtr) filter out all output of mariabackup or mariadb-backup.

I noticed this spamming when removing the log block structure and log block parser in ~~MDEV-14425~~ for 10.8, but I did not investigate it very deep.

If this really is a regression in 10.6, then ~~MDEV-21452~~ could have caused this.

Marko Mäkelä added a comment - 2022-03-25 15:29 Our regression tests ( mtr ) filter out all output of mariabackup or mariadb-backup . I noticed this spamming when removing the log block structure and log block parser in MDEV-14425 for 10.8, but I did not investigate it very deep. If this really is a regression in 10.6, then MDEV-21452 could have caused this.

Marko Mäkelä made changes - 2022-03-25 15:29

Assignee

Vladislav Lesin [ vlad.lesin ]

Ralf Gebhardt made changes - 2022-04-07 11:24

Link

This issue blocks TODO-3399 [ TODO-3399 ]

Julien Fritsch made changes - 2022-04-12 07:45

Fix Version/s

10.6 [ 24028 ]

Vladislav Lesin made changes - 2022-04-15 10:20

Status

Open [ 1 ]

In Progress [ 3 ]

Vladislav Lesin added a comment - 2022-04-15 15:11

In 10.5 polling interval is measured in microseconds:

static os_thread_ret_t DECLARE_THREAD(log_copying_thread)(void*)

...

        for (;;) {

                os_event_reset(log_copying_stop);

                os_event_wait_time_low(log_copying_stop,

                                       xtrabackup_log_copy_interval * 1000U,

0);

                if (xtrabackup_copy_logfile()) {

                        break;

...

...

os_event_wait_time_low(

/*===================*/

        os_event_t      event,                  /*!< in/out: event to wait */

        ulint           time_in_usec,           /*!< in: timeout in

                                                microseconds, or

                                                OS_SYNC_INFINITE_TIME */

        int64_t         reset_sig_count)        /*!< in: zero or the value

While in 10.6 the interval is measured in nanoseconds:

static void log_copying_thread()

...

  while (!xtrabackup_copy_logfile() &&

         (!metadata_to_lsn || metadata_to_lsn > log_copy_scanned_lsn))

    timespec abstime;

    set_timespec_nsec(abstime, 1000ULL * xtrabackup_log_copy_interval);

    mysql_cond_timedwait(&log_copying_stop, &log_sys.mutex, &abstime);

...

The workaround is to increase --log-copy-interval by a thousand times until it's fixed.

Vladislav Lesin added a comment - 2022-04-15 15:11 In 10.5 polling interval is measured in microseconds: static os_thread_ret_t DECLARE_THREAD(log_copying_thread)( void *) { ... for (;;) { os_event_reset(log_copying_stop); os_event_wait_time_low(log_copying_stop, xtrabackup_log_copy_interval * 1000U, 0 ); if (xtrabackup_copy_logfile()) { break ; } ... } ... } os_event_wait_time_low( /*===================*/ os_event_t event, /*!< in/out: event to wait */ ulint time_in_usec, /*!< in: timeout in microseconds, or OS_SYNC_INFINITE_TIME */ int64_t reset_sig_count) /*!< in: zero or the value While in 10.6 the interval is measured in nanoseconds: static void log_copying_thread() { ... while (!xtrabackup_copy_logfile() && (!metadata_to_lsn || metadata_to_lsn > log_copy_scanned_lsn)) { timespec abstime; set_timespec_nsec(abstime, 1000ULL * xtrabackup_log_copy_interval); mysql_cond_timedwait(&log_copying_stop, &log_sys.mutex, &abstime); } ... } The workaround is to increase --log-copy-interval by a thousand times until it's fixed.

Vladislav Lesin made changes - 2022-04-15 15:23

Summary

MariaBackup 10.6 ">> log scanned up to (...)" print too fast

mariabackup --log-copy-interval is measured in microseconds in 10.5 and in nanoseconds in 10.6

Vladislav Lesin added a comment - 2022-04-19 14:14

The bug was caused by 38fd7b7d9170.

Vladislav Lesin added a comment - 2022-04-19 14:14 The bug was caused by 38fd7b7d9170.

Vladislav Lesin made changes - 2022-04-19 14:14

Assignee	Vladislav Lesin [ vlad.lesin ]	Marko Mäkelä [ marko ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Marko Mäkelä added a comment - 2022-04-19 14:18

Thank you for the analysis. I’m glad that it was so trivial after all. I hope that you can figure out some way to test it in mtr.

Marko Mäkelä added a comment - 2022-04-19 14:18 Thank you for the analysis. I’m glad that it was so trivial after all. I hope that you can figure out some way to test it in mtr .

Marko Mäkelä made changes - 2022-04-19 14:18

Assignee	Marko Mäkelä [ marko ]	Vladislav Lesin [ vlad.lesin ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Marko Mäkelä made changes - 2022-04-19 14:24

Summary

mariabackup --log-copy-interval is measured in microseconds in 10.5 and in nanoseconds in 10.6

mariabackup --log-copy-interval is measured in milliseconds in 10.5 and in microseconds in 10.6

Vladislav Lesin made changes - 2022-04-21 09:24

Status

Stalled [ 10000 ]

In Progress [ 3 ]

Vladislav Lesin made changes - 2022-04-21 13:15

Fix Version/s		10.6.8 [ 27506 ]
Fix Version/s		10.7.4 [ 27504 ]
Fix Version/s		10.8.3 [ 27502 ]
Fix Version/s		10.9.1 [ 27114 ]
Fix Version/s	10.6 [ 24028 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Ralf Gebhardt made changes - 2022-06-27 09:20

Link

This issue relates to ~~MDEV-25765~~ [ ~~MDEV-25765~~ ]

Jira Automation (IT) made changes - 2024-07-04 01:40

Zendesk Related Tickets

166500

People

Assignee:: Vladislav Lesin

Reporter:: Harvey Cooper

Votes:: 1 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2022-02-23 02:59

Updated:: 2024-07-07 20:41

Resolved:: 2022-04-21 13:15

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration