non-ISO timestamp format handling

[Gerus87]

CoentOS 7, PostgreSQL 11.3, pg_probackup-11 2.1.2
Пытаюсь создать полную резервную копию командой
pg_probackup-11 backup -B /pg_probackup/ --instance test_db -b FULL -j 2 --stream --progress --compress
Процесс не выдает ошибки или варнинги, просто останавливается и не продолжается после копирования файлов данных:
INFO: Progress: (12010/12010). Process file "/pg_probackup/11/data/base/21946/1032599"
INFO: Data files are transfered
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
Следующий этап - валидация - не начинается. Процесс висел 5 суток - без результата, бекап не завершается
Просьба помочь, подсказать куда смотреть, что поправить

[gsmolk]

Добрый день!
А процесс еще живой?

ps aufx | grep pg_probackup

[Gerus87]

Процесс живет, да, не умирает, статус бекапа RUNNING

[gsmolk]

Супер.
Давайте посмотрим, где он там висит.

1. Поставьте, пожалуйста, debuginfo пакет и gdb:
   yum install pg_probackup-11-debuginfo
   yum install gdb
2. Смотрим стек-трейс:
   gdb -p pid_number --ex bt --batch

[Gerus87]

Установил. стек-трейс скину позже, т.к. недавно перезапустил сбор бекапа, а БД большая

[gsmolk]

Лучше сразу сейчас его скинуть, это не займет много времени, а если процесс исчезнет, то разобраться уже не получится.

[Gerus87]

Хорошо, но после нового запуска пока все ок)

[root@db ~]# ps aufx | grep pg_probackup
postgres  97758  795  0.0 760452 27792 pts/4    Sl+  11:18 583:28      \_ pg_probackup-11 backup -B /fs2/backup --instance=tfoms_200 -b FULL -j 8 --stream -d tfoms_200 -p 5200 -U postgres -w --compress-algorithm=zlib --compress-level=9 --log-level-console=verbose --progress --log-level-file=verbose --force
root      58809  0.0  0.0 112728   984 pts/3    S+   12:31   0:00          \_ grep --color=auto pg_probackup
[root@db ~]# gdb -p 97758 --ex bt --batch

warning: the debug information found in "/usr/lib/debug//usr/bin/pg_probackup-11.debug" does not match "/usr/bin/pg_probackup-11" (CRC mismatch).


warning: the debug information found in "/usr/lib/debug/usr/bin/pg_probackup-11.debug" does not match "/usr/bin/pg_probackup-11" (CRC mismatch).

[New LWP 97784]
[New LWP 97783]
[New LWP 97782]
[New LWP 97781]
[New LWP 97780]
[New LWP 97779]
[New LWP 97778]
[New LWP 97777]
[New LWP 97767]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f067e6f3f47 in pthread_join () from /lib64/libpthread.so.0
#0  0x00007f067e6f3f47 in pthread_join () from /lib64/libpthread.so.0
#1  0x0000000000412dde in do_backup_instance ()
#2  0x0000000000414062 in do_backup ()
#3  0x0000000000404715 in main ()
[root@db ~]# 

[gsmolk]

А вот еще такую команду выполните, пожалуйста:

gdb -p 97758 -ex 'thread apply all bt' --batch

[Gerus87]

warning: the debug information found in "/usr/lib/debug//usr/bin/pg_probackup-11.debug" does not match "/usr/bin/pg_probackup-11" (CRC mismatch).


warning: the debug information found in "/usr/lib/debug/usr/bin/pg_probackup-11.debug" does not match "/usr/bin/pg_probackup-11" (CRC mismatch).

[New LWP 97784]
[New LWP 97783]
[New LWP 97782]
[New LWP 97781]
[New LWP 97780]
[New LWP 97779]
[New LWP 97778]
[New LWP 97777]
[New LWP 97767]
[Thread debugging using libthread_db enabled]

Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f067e6f3f47 in pthread_join () from /lib64/libpthread.so.0

Thread 10 (Thread 0x7f067a50f700 (LWP 97767)):
#0  0x00007f067e1fcf73 in select () from /lib64/libc.so.6
#1  0x0000000000426cc4 in CopyStreamReceive ()
#2  0x0000000000427672 in ReceiveXlogStream ()
#3  0x000000000041167d in StreamLog ()
#4  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#5  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x7f0679d0e700 (LWP 97777)):
#0  0x00007f067e4d7d16 in longest_match () from /lib64/libz.so.1
#1  0x00007f067e4d8690 in deflate_slow () from /lib64/libz.so.1
#2  0x00007f067e4d9624 in deflate () from /lib64/libz.so.1
#3  0x00007f067e4e15bd in compress2 () from /lib64/libz.so.1
#4  0x00000000004172ca in do_compress ()
#5  0x00000000004173a7 in compress_and_backup_page ()
#6  0x0000000000417cee in backup_data_file ()
#7  0x000000000041152b in backup_files ()
#8  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x7f067950d700 (LWP 97778)):
#0  0x00007f067e4d8464 in deflate_slow () from /lib64/libz.so.1
#1  0x00007f067e4d9624 in deflate () from /lib64/libz.so.1
#2  0x00007f067e4e15bd in compress2 () from /lib64/libz.so.1
#3  0x00000000004172ca in do_compress ()
#4  0x00000000004173a7 in compress_and_backup_page ()
#5  0x0000000000417cee in backup_data_file ()
#6  0x000000000041152b in backup_files ()
#7  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#8  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x7f0678d0c700 (LWP 97779)):
#0  0x00007f067e4d7d16 in longest_match () from /lib64/libz.so.1
#1  0x00007f067e4d8690 in deflate_slow () from /lib64/libz.so.1
#2  0x00007f067e4d9624 in deflate () from /lib64/libz.so.1
#3  0x00007f067e4e15bd in compress2 () from /lib64/libz.so.1
#4  0x00000000004172ca in do_compress ()
#5  0x00000000004173a7 in compress_and_backup_page ()
#6  0x0000000000417cee in backup_data_file ()
#7  0x000000000041152b in backup_files ()
#8  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x7f066bfff700 (LWP 97780)):
#0  0x00007f067e4d7d16 in longest_match () from /lib64/libz.so.1
#1  0x00007f067e4d8690 in deflate_slow () from /lib64/libz.so.1
#2  0x00007f067e4d9624 in deflate () from /lib64/libz.so.1
#3  0x00007f067e4e15bd in compress2 () from /lib64/libz.so.1
#4  0x00000000004172ca in do_compress ()
#5  0x00000000004173a7 in compress_and_backup_page ()
#6  0x0000000000417cee in backup_data_file ()
#7  0x000000000041152b in backup_files ()
#8  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7f066b7fe700 (LWP 97781)):
#0  0x00007f067e196fe0 in __memset_sse2 () from /lib64/libc.so.6
#1  0x00007f067e4d91c1 in deflateReset () from /lib64/libz.so.1
#2  0x00007f067e4dab44 in deflateInit_ () from /lib64/libz.so.1
#3  0x00007f067e4e158d in compress2 () from /lib64/libz.so.1
#4  0x00000000004172ca in do_compress ()
#5  0x00000000004173a7 in compress_and_backup_page ()
#6  0x0000000000417cee in backup_data_file ()
#7  0x000000000041152b in backup_files ()
#8  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7f066affd700 (LWP 97782)):
#0  0x00007f067e6f9f63 in pread64 () from /lib64/libpthread.so.0
#1  0x000000000040b607 in fio_pread ()
#2  0x00000000004175ee in prepare_page.isra.2 ()
#3  0x0000000000417cb8 in backup_data_file ()
#4  0x000000000041152b in backup_files ()
#5  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x7f066a7fc700 (LWP 97783)):
#0  0x00007f067e4d7d16 in longest_match () from /lib64/libz.so.1
#1  0x00007f067e4d8690 in deflate_slow () from /lib64/libz.so.1
#2  0x00007f067e4d9624 in deflate () from /lib64/libz.so.1
#3  0x00007f067e4e15bd in compress2 () from /lib64/libz.so.1
#4  0x00000000004172ca in do_compress ()
#5  0x00000000004173a7 in compress_and_backup_page ()
#6  0x0000000000417cee in backup_data_file ()
#7  0x000000000041152b in backup_files ()
#8  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7f0669ffb700 (LWP 97784)):
#0  0x00007f067e4d8456 in deflate_slow () from /lib64/libz.so.1
#1  0x00007f067e4d9624 in deflate () from /lib64/libz.so.1
#2  0x00007f067e4e15bd in compress2 () from /lib64/libz.so.1
#3  0x00000000004172ca in do_compress ()
#4  0x00000000004173a7 in compress_and_backup_page ()
#5  0x0000000000417cee in backup_data_file ()
#6  0x000000000041152b in backup_files ()
#7  0x00007f067e6f2dd5 in start_thread () from /lib64/libpthread.so.0
#8  0x00007f067e205ead in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f067ed5a980 (LWP 97758)):
#0  0x00007f067e6f3f47 in pthread_join () from /lib64/libpthread.so.0
#1  0x0000000000412dde in do_backup_instance ()
#2  0x0000000000414062 in do_backup ()
#3  0x0000000000404715 in main ()

[gsmolk]

Удивительно, бэкап висит в zlib`е.
А до этого бэкапы нормально снимались?

[gsmolk]

Стоп:

postgres  97758  795  0.0 760452 27792 pts/4    Sl+  11:18 583:28

Тут нет пяти суток. Я правильно понимаю, что выполняющегося 5 суток бэкапа уже нет?

[Gerus87]

Да, я поэтому предлагал позже скинуть стек-трейс, когда закончится копирование файлов данных.
Прежде pg_probackup для резервного копирования не использовался, просто дампили БД pg_dump'ом. Затем, сбор дампа перестал укладываться в приемлемые сроки. Было решено настроить инкрементальное резервное копирование утилитой pg_probackup.
Пока остановился на этапе сбора полного бекапа, с чем и обратился сюда)

[gsmolk]

Ага, понял.
Ну будем надеяться, что воспроизведется.
Несколько замечаний:

1. Обновитесь до 2.1.5
2. флага --force у нас нет, точнее он есть, но пока ничего не делает.
3. --compress-level=9 почти не имеет смысла использовать, в большинстве случаев уровень компрессии >1 не даёт выигрыша по размеру, но значительно замедляет выполнение.

[Gerus87]

Хорошо, жду окончания, скидываю стек-трейс, обновляюсь
Спасибо за замечания!)

[gsmolk]

С --compress-level=9 Вы будете долго ждать =)