From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id 4B9F469943 for ; Mon, 7 Dec 2020 03:51:53 +0100 (CET) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 3A3991E794 for ; Mon, 7 Dec 2020 03:51:23 +0100 (CET) Received: from EUR05-VI1-obe.outbound.protection.outlook.com (mail-vi1eur05on2060b.outbound.protection.outlook.com [IPv6:2a01:111:f400:7d00::60b]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by firstgate.proxmox.com (Proxmox) with ESMTPS id AF1B71E78B for ; Mon, 7 Dec 2020 03:51:20 +0100 (CET) ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=IppwQ+VE91gPrjHFRoGXaKzqw797KZWoIcOTpSNgCw9U8VgeVgiaOZTDnj8tui3TH7vXx5Zkx0FJeWIZ3EDR+bsvZ1mAp/m6hh7aW4Hk/6O+r7fCFR+SY/MIWu2GjQf6vMxjh4q4WCO0XboSQ++C7EPgBph4yCK2pgxQbOyq291pTYLXWhRdPwdbrNTZq2XBVPG8uZpwEIiECbQ5UfuDuF556PcZBwey7Y87L3r+ECXMPY8FnmJC97oRTh3iKwvJQFFIF5AbmeXov9BGQ6+Xd9Ch68HewKnRoK2dnSYU3u6revdaoILLD5+8MutymWm0k/mJ1pXRSSF064xHEdiToA== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=microsoft.com; s=arcselector9901; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=XRBPRHaUppNjvu7KIdZBqN7IemAsqfl6FrWu+WXf0LU=; b=Bd/AUCXfXLGyKSHLKVCArYhb/VmGsE3mxev4s2uz9UFM3e6sqhsLe+d5P3Bz00BimjysmzXyhZTer81w3Ic52S70Zg8P8j6uI/DJ45YMSlkCxmZe2jg/L6tkaBhdegIr8f1mgfcVMB21lPh99wBf01AO5/3+cG4KZsrIL4JV9fO6QU+sSfhdXvVLcfkOV1OgPtUPl56nkbR4PX27vpXjmUZUwlOZiO4AOre2Z6OrYiC5u4s5iDP0wiYpj4qSw54HFSPwokNOkIWwYz0Hb/wY1FXWo29Iw/XLGbTTcIW1N3M1n1I/v9qjO0lwrcsQ750qw8jbci//1ZXTvSqPcehupQ== ARC-Authentication-Results: i=1; mx.microsoft.com 1; spf=pass smtp.mailfrom=logics.de; dmarc=pass action=none header.from=logics.de; dkim=pass header.d=logics.de; arc=none DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=logics99.onmicrosoft.com; s=selector2-logics99-onmicrosoft-com; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=XRBPRHaUppNjvu7KIdZBqN7IemAsqfl6FrWu+WXf0LU=; b=OWiWauGjrroxlAbzxaNw7fdJcREwcX/GEYUE7xta38CnB6crJrQc6DvWgDjDFzpNAlU4OgMDZowe71CVHDTtWEsxBBIGM0/KbcAbcH38R6c5vu/anrE2fc4UONeH/xjxQY4yW++52RA+bYpztestes9rhaHIkqraKZ+ulbHfzRo= Received: from AM0PR09MB2754.eurprd09.prod.outlook.com (2603:10a6:208:12e::18) by AM0PR09MB3444.eurprd09.prod.outlook.com (2603:10a6:208:179::28) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.3632.19; Mon, 7 Dec 2020 02:51:13 +0000 Received: from AM0PR09MB2754.eurprd09.prod.outlook.com ([fe80::68c5:8966:920c:8d24]) by AM0PR09MB2754.eurprd09.prod.outlook.com ([fe80::68c5:8966:920c:8d24%3]) with mapi id 15.20.3632.023; Mon, 7 Dec 2020 02:51:12 +0000 From: Niko Fellner To: "pbs-devel@lists.proxmox.com" Thread-Topic: Re: [pbs-devel] parallelize restore.rs fn restore_image: problems in Thread-Index: AdbMOh4yYqVdr57yS9+NT97usb+lOw== Date: Mon, 7 Dec 2020 02:51:12 +0000 Message-ID: Accept-Language: de-DE, en-US Content-Language: de-DE X-MS-Has-Attach: X-MS-TNEF-Correlator: authentication-results: lists.proxmox.com; dkim=none (message not signed) header.d=none;lists.proxmox.com; dmarc=none action=none header.from=logics.de; x-originating-ip: [80.81.12.137] x-ms-publictraffictype: Email x-ms-office365-filtering-correlation-id: d820b364-1921-4c31-43cb-08d89a5af571 x-ms-traffictypediagnostic: AM0PR09MB3444: x-microsoft-antispam-prvs: x-ms-oob-tlc-oobclassifiers: OLM:6790; x-ms-exchange-senderadcheck: 1 x-microsoft-antispam: BCL:0; x-microsoft-antispam-message-info: 1AfdgZEf2wOTseoneG1eEn8J1OQhj5t1vo9mGMbcF5n1RWhxgZlT3AYLMBcLkeUUbo8rVpQ9jVSca+JNXyGQOrBVQyWJ3m1Ge7sSINzpeg/8MMXEscvIK+PBlxcEnn1UQqYAGtKXXCOfQuOhW5y2bFhHV2iEu4JcbMar/rSR7fbq8dwYPcpdpcKzgRJx3p7MLFRWaW8cOKqLtweE82vhUlu9da0WT9dL5EyPtbdb4+gUdLSGG9d8yiukbroe3jur/MYpVcTOeC/H0wWM+8BdviBUz8wfo9BuVBqe2LXvJk5zpwj8rXGBapbQVShLnrIRN8h+BAONhMnxbhyCgiBIiA== x-forefront-antispam-report: CIP:255.255.255.255; CTRY:; LANG:en; SCL:1; SRV:; IPV:NLI; SFV:NSPM; H:AM0PR09MB2754.eurprd09.prod.outlook.com; PTR:; CAT:NONE; SFS:(136003)(39830400003)(346002)(366004)(396003)(376002)(76116006)(186003)(71200400001)(8936002)(8676002)(9686003)(83380400001)(6506007)(478600001)(26005)(33656002)(52536014)(86362001)(5660300002)(64756008)(55016002)(6916009)(66476007)(30864003)(66446008)(7696005)(66946007)(316002)(2906002)(66556008)(579004)(559001); DIR:OUT; SFP:1101; x-ms-exchange-antispam-messagedata: =?us-ascii?Q?LzPsQ1wCJ+0Qhi69vO2cov7d5sGt5ghWMDNjah4HAesaDus7ZFbKUqQgrN19?= =?us-ascii?Q?4zcfSW8cF7DsGVXBf4f1ZPmvEt5GlX30XkIwjft91E5OKgBpm6YDelKia8F/?= =?us-ascii?Q?EoiNUE3ON/mUOA9vmc9fLJ9OggkRGja1UtD0UGs8JQgACV930pyGjytbdjri?= =?us-ascii?Q?FVo71voGXcS9iv5MUpLf1OZgnpkAP75qFRf3d7UzXvjZmHuyuWtDSf9FwfeT?= =?us-ascii?Q?hE4vGYY6pSjIvJiILek/MHaOf6ENzCVYsPRqCL/xuOr+76Uqfd3bHD7wb+J0?= =?us-ascii?Q?HlrtgFi27GiZxch5PZYcHOKzYK/9YJ45tAPxHPXuLY1J8fY7VmTQlI0sNCVm?= =?us-ascii?Q?6Eu7BmjAcOyMIozpQmfANswrouBLnqXla0pW9Z81b9dmSHi+8tTay9XFHGnK?= =?us-ascii?Q?x3RqI1948Y4ZL2kvJE1ZVckSuiiPLj8Xd3z8NEyfjqpMbOmzEBygS3nibrnD?= =?us-ascii?Q?G7fNTohObeBJSOhkYkZbNz60atIT/M7gGgXhOGox0iRLl+w8zCAauR/bjxak?= =?us-ascii?Q?4J5bHuui+bHyNF28KiO9m9cbFZVM55JAwX1c2ErmP+QY8yJZEcoIftlG7NeL?= =?us-ascii?Q?yWc9CF6KcdWlpF4qrXNdV7T01ATpBQMm+PPYQOeerQNlGdRAHrTrQUmjHnWg?= =?us-ascii?Q?or4urTgKtTvAxqulsfJ+wMgiTt7NnQy83VmxNuxqQlwid73wYmuqwGOd0BbF?= =?us-ascii?Q?WG09/Yo9sdUX0rv3Vwe0cCHLnOBhVArZ6F4XQHMBWQr0MXqPk4eRuTfkUPR6?= =?us-ascii?Q?45js1uIqhiS2vvWpNNuQM+gkieAn3+q3M6KVX0VWcCHsjAB713JnvSrqAWop?= =?us-ascii?Q?PTVBu1iUI3Q4dOxmQ1i6Q4bcoOhtG2xDeCB1fCH2EIziuTSwwLnTySHF5uqZ?= =?us-ascii?Q?6bgr4SMEPMjEbP4cHCqGDEFQ6YCCuyKTbD8FG0LsVBUPDnn37/mlrdjvytcA?= =?us-ascii?Q?QoU6K314Qg2hcH0LMwH4oVjiZugVxGpl8e/6MZC0zPA=3D?= x-ms-exchange-transport-forked: True Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 X-OriginatorOrg: logics.de X-MS-Exchange-CrossTenant-AuthAs: Internal X-MS-Exchange-CrossTenant-AuthSource: AM0PR09MB2754.eurprd09.prod.outlook.com X-MS-Exchange-CrossTenant-Network-Message-Id: d820b364-1921-4c31-43cb-08d89a5af571 X-MS-Exchange-CrossTenant-originalarrivaltime: 07 Dec 2020 02:51:12.6941 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: fdfa9215-653f-430f-b8ab-a8728140f97a X-MS-Exchange-CrossTenant-mailboxtype: HOSTED X-MS-Exchange-CrossTenant-userprincipalname: cA2VzNMWQHNNXehwDxXY+luoJE6kPNScZmH0JiH1FZ+FCUezbLc495EDtrhRKBTXcEREorvMnvC/4ubvCilFYAMreO0ehCtGebbWawR704M= X-MS-Exchange-Transport-CrossTenantHeadersStamped: AM0PR09MB3444 X-SPAM-LEVEL: Spam detection results: 0 AWL -0.100 Adjusted score from AWL reputation of From: address DKIM_SIGNED 0.1 Message has a DKIM or DK signature, not necessarily valid DKIM_VALID -0.1 Message has at least one valid DKIM or DK signature SPF_HELO_PASS -0.001 SPF: HELO matches SPF record SPF_PASS -0.001 SPF: sender matches SPF record Subject: Re: [pbs-devel] parallelize restore.rs fn restore_image: problems in X-BeenThere: pbs-devel@lists.proxmox.com X-Mailman-Version: 2.1.29 Precedence: list List-Id: Proxmox Backup Server development discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 07 Dec 2020 02:51:53 -0000 By using mutex (AtomicBool - compare_exchange) I found out that only the wr= ite_zero_callback and write_data_callback are problematic (no mutex -> segf= aults). Maybe anyone can find out why? Furthermore I am using "ReadChunk::read_chunk(&chunk_reader_clone, &digest)= ?" again instead of "AsyncReadChunk::read_chunk(&chunk_reader_clone, &diges= t).await?"; the latter one sometimes does not return, especially when acces= sed by more than 1 thread simultaneously. Some performance tests of a 32 GiB VM (64% zeroes; 10 GB pure random data): - Original 1 thread sync (bytes=3D34359738368, duration=3D224.78s, speed=3D= 145.78MB/s) - When putting a mutex around the read_chunk part, too, I had no performanc= e improvement at all, no matter how many futures and threads I use. So with= mutex read_chunk, 1 future was the fastest (bytes=3D34359738368, zeroes=3D= 22322085888, duration=3D224.75s, speed=3D145.80MB/s) - Using 2 futures, 4 core_threads, 6 max_threads: (bytes=3D34359738368, zer= oes=3D22322085888, duration=3D188.53s, speed=3D173.81MB/s) - Using 3 futures, 4 core_threads, 6 max_threads: (bytes=3D34359738368, zer= oes=3D22322085888, duration=3D176.08s, speed=3D186.10MB/s) - Using 6 futures, 6 core_threads, 12 max_threads: (bytes=3D34359738368, ze= roes=3D22322085888, duration=3D160.12s, speed=3D204.65MB/s) - Using 10 futures, 12 core_threads, 24 max_threads: (bytes=3D34359738368, = zeroes=3D22322085888, duration=3D154.33s, speed=3D212.32MB/s) - Using 12 futures, 12 core_threads, 24 max_threads: (bytes=3D34359738368, = zeroes=3D22322085888, duration=3D153.04s, speed=3D214.11MB/s) Host: - my dev+test PVE/PBS runs as a VM with 12 vCPUs within an productive PVE h= ost (which is running on a dedicated host on Hetzner) - CPU: Intel(R) Xeon(R) CPU E5-1650 v3 (6 core, 12 threads) - Memory: 256 GB - Source AND target was at the same SSD "SAMSUNG MZ7LM480HCHP-00003" (for p= erformance reasons I usually choose a different source and target .. but he= re it's just a test VM) - Maybe next week I'll test at a bigger Host again (Azure 2x 2TB NVMe with = lots of vCPUs...).=20 - But still I can't write with more than 1 thread simultaneously...maybe an= yone can help out here? (Maybe Dietmar's pull.rs mechanism could help?) diff --git a/Cargo.toml b/Cargo.toml index 7f29d0a..c87bf5a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,9 +27,9 @@ lazy_static =3D "1.4" libc =3D "0.2" once_cell =3D "1.3.1" openssl =3D "0.10" -proxmox =3D { version =3D "0.7.0", features =3D [ "sortable-macro", "api-m= acro" ] } -proxmox-backup =3D { git =3D "git://git.proxmox.com/git/proxmox-backup.git= ", tag =3D "v1.0.4" } -#proxmox-backup =3D { path =3D "../proxmox-backup" } +proxmox =3D { version =3D "0.8.0", features =3D [ "sortable-macro", "api-m= acro" ] } +#proxmox-backup =3D { git =3D "git://git.proxmox.com/git/proxmox-backup.gi= t", tag =3D "v1.0.4" } +proxmox-backup =3D { path =3D "../proxmox-backup" } serde_json =3D "1.0" tokio =3D { version =3D "0.2.9", features =3D [ "blocking", "fs", "io-util= ", "macros", "rt-threaded", "signal", "stream", "tcp", "time", "uds" ] } bincode =3D "1.0" diff --git a/src/capi_types.rs b/src/capi_types.rs index 1b9abc1..de08523 100644 --- a/src/capi_types.rs +++ b/src/capi_types.rs @@ -1,5 +1,5 @@ use anyhow::Error; -use std::os::raw::{c_char, c_void, c_int}; +use std::os::raw::{c_uchar, c_char, c_void, c_int}; use std::ffi::CString; =20 pub(crate) struct CallbackPointers { @@ -48,3 +48,15 @@ pub struct ProxmoxRestoreHandle; /// Opaque handle for backups jobs #[repr(C)] pub struct ProxmoxBackupHandle; + +#[derive(Copy, Clone)] +pub(crate) struct SendRawPointer { + pub callback: extern "C" fn(*mut c_void, u64, *const c_uchar, u64) -> = c_int, + pub callback_data: *mut c_void +} +unsafe impl std::marker::Send for SendRawPointer {} +impl SendRawPointer { + pub fn call_itself(self, offset: u64, data: *const c_uchar, len: u64) = -> i32 { + return (self.callback)(self.callback_data, offset, data, len); + } +} \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs index b755014..39baddb 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -816,13 +816,15 @@ pub extern "C" fn proxmox_restore_image( =20 let archive_name =3D tools::utf8_c_string(archive_name)? .ok_or_else(|| format_err!("archive_name must not be NULL"))?; + =20 + let send_raw_pointer =3D SendRawPointer { callback, callback_data = }; =20 let write_data_callback =3D move |offset: u64, data: &[u8]| { - callback(callback_data, offset, data.as_ptr(), data.len() as u= 64) + return send_raw_pointer.call_itself(offset, data.as_ptr(), dat= a.len() as u64) }; =20 let write_zero_callback =3D move |offset: u64, len: u64| { - callback(callback_data, offset, std::ptr::null(), len) + return send_raw_pointer.call_itself(offset, std::ptr::null(), = len) }; =20 proxmox_backup::tools::runtime::block_on( diff --git a/src/restore.rs b/src/restore.rs index 24983dd..b141827 100644 --- a/src/restore.rs +++ b/src/restore.rs @@ -66,8 +66,10 @@ impl RestoreTask { let mut builder =3D tokio::runtime::Builder::new(); builder.threaded_scheduler(); builder.enable_all(); - builder.max_threads(6); - builder.core_threads(4); + //builder.max_threads(6); + //builder.core_threads(4); + builder.max_threads(24); + builder.core_threads(12); builder.thread_name("proxmox-restore-worker"); builder }); @@ -106,12 +108,12 @@ impl RestoreTask { pub fn runtime(&self) -> tokio::runtime::Handle { self.runtime.handle().clone() } - - pub async fn restore_image( + =20 + pub async fn restore_image i32, B: 'static + Copy + Send + Fn(u64, u64) -> i32> ( &self, archive_name: String, - write_data_callback: impl Fn(u64, &[u8]) -> i32, - write_zero_callback: impl Fn(u64, u64) -> i32, + write_data_callback: A, + write_zero_callback: B, verbose: bool, ) -> Result<(), Error> { =20 @@ -148,46 +150,135 @@ impl RestoreTask { most_used, ); =20 - let mut per =3D 0; - let mut bytes =3D 0; - let mut zeroes =3D 0; + let per =3D std::sync::Arc::new(std::sync::atomic::AtomicUsize::ne= w(0)); + let bytes =3D std::sync::Arc::new(std::sync::atomic::AtomicUsize::= new(0)); + let zeroes =3D std::sync::Arc::new(std::sync::atomic::AtomicUsize:= :new(0)); + =20 + let index_chunk_size =3D index.chunk_size; + let index_count =3D index.index_count(); + eprintln!("index_count =3D {}, index_chunk_size: {}", index_count,= index_chunk_size); + eprintln!("BEGIN: push and await tasks"); + =20 + //let mut tokio_handles =3D vec![]; // Vec::with_capacity(index_co= unt); + =20 + use futures::stream::{StreamExt}; + let mut futs =3D futures::stream::FuturesUnordered::new(); + //let mut futs =3D futures::stream::FuturesOrdered::new(); // not = helpful =20 let start_time =3D std::time::Instant::now(); - - for pos in 0..index.index_count() { - let digest =3D index.index_digest(pos).unwrap(); - let offset =3D (pos*index.chunk_size) as u64; - if digest =3D=3D &zero_chunk_digest { - let res =3D write_zero_callback(offset, index.chunk_size a= s u64); - if res < 0 { - bail!("write_zero_callback failed ({})", res); - } - bytes +=3D index.chunk_size; - zeroes +=3D index.chunk_size; - } else { - let raw_data =3D ReadChunk::read_chunk(&chunk_reader, &dig= est)?; - let res =3D write_data_callback(offset, &raw_data); - if res < 0 { - bail!("write_data_callback failed ({})", res); + =20 + // I tried out where we need a lock. Actually only needed for read= ing. + let locked =3D Arc::new(std::sync::atomic::AtomicBool::new(false))= ; // false =3D unlocked =3D allowed to read + let locked_progress =3D Arc::new(std::sync::atomic::AtomicBool::ne= w(false)); // false =3D unlocked =3D allowed to read + + for pos in 0..index_count { + let chunk_reader_clone =3D chunk_reader.clone(); + let index_digest =3D index.index_digest(pos).unwrap().clone(); + let per =3D std::sync::Arc::clone(&per); + let bytes =3D std::sync::Arc::clone(&bytes); + let zeroes =3D std::sync::Arc::clone(&zeroes); + let locked_clone =3D Arc::clone(&locked); + let locked_progress_clone =3D Arc::clone(&locked_progress); + //tokio_handles.push( + futs.push( + tokio::spawn( + //tokio::task::spawn_blocking( + async move { + //move || { + let digest =3D &index_digest; + let offset =3D (pos*index_chunk_size) as u64; + //eprintln!("{} BEGIN offset {}", pos, offset); + //eprintln!("{} BEGIN", pos); + if digest =3D=3D &zero_chunk_digest { + while locked_clone.compare_exchange(false, tru= e, std::sync::atomic::Ordering::Acquire, std::sync::atomic::Ordering::Acqui= re).is_err() {std::thread::yield_now()} // if it's unlocked (false): set to= locked (true), else waits + //eprintln!("{} write_zero_callback ENTERED", = pos); + let res =3D write_zero_callback(offset, index_= chunk_size as u64); + //eprintln!("{} write_zero_callback LEFT with = res: {}, offset: {}", pos, res, offset); + locked_clone.store(false, std::sync::atomic::O= rdering::Release); // unlock it + if res < 0 { + bail!("write_zero_callback failed ({})", r= es); + } + bytes.fetch_add(index_chunk_size, std::sync::a= tomic::Ordering::SeqCst); + zeroes.fetch_add(index_chunk_size, std::sync::= atomic::Ordering::SeqCst); + } else { + //eprintln!("{} BEFORE read_chunk: offset: {}"= , pos, offset); + //while locked_clone.compare_exchange(false, t= rue, std::sync::atomic::Ordering::Acquire, std::sync::atomic::Ordering::Acq= uire).is_err() {std::thread::yield_now()} // if it's unlocked (false): set = to locked (true), else waits + //eprintln!("{} read_chunk ENTERED", pos); + let raw_data =3D ReadChunk::read_chunk(&chunk_= reader_clone, &digest)?; // works fine when we have a mutex around the foll= owing writing part + //let raw_data =3D AsyncReadChunk::read_chunk(= &chunk_reader_clone, &digest).await?; // sometimes does not return, especia= lly when accessed by more than 1 thread, no matter if mutex or not + //eprintln!("{} AFTER read_chunk: offset: {}",= pos, offset); + //eprintln!("{} read_chunk LEFT", pos); + //locked_clone.store(false, std::sync::atomic:= :Ordering::Release); // unlock it + =20 + while locked_clone.compare_exchange(false, tru= e, std::sync::atomic::Ordering::Acquire, std::sync::atomic::Ordering::Acqui= re).is_err() {std::thread::yield_now()} // if it's unlocked (false): set to= locked (true), else waits + //eprintln!("{} write_data_callback ENTERED", = pos); + let res =3D write_data_callback(offset, &raw_d= ata); + //eprintln!("{} AFTER write_data_callback with= res: {}, offset: {}", pos, res, offset); + //eprintln!("{} write_data_callback LEFT with = res: {}", pos, res); + locked_clone.store(false, std::sync::atomic::O= rdering::Release); // unlock it + if res < 0 { + bail!("write_data_callback failed ({})", r= es); + } + bytes.fetch_add(raw_data.len(), std::sync::ato= mic::Ordering::SeqCst); + } + if verbose { + // mutex only helps for avoiding to show the s= ame line twice by different threads. + // without mutex we have no crashes either. + // the mutex here doesn't cost any measurable = performance + while locked_progress_clone.compare_exchange(f= alse, true, std::sync::atomic::Ordering::Acquire, std::sync::atomic::Orderi= ng::Acquire).is_err() {std::thread::yield_now()} // if it's unlocked (false= ): set to locked (true), else waits + //eprintln!("{} progress ENTERED", pos); + let next_per =3D ((pos+1)*100)/index_count; + let currPer =3D per.load(std::sync::atomic::Or= dering::SeqCst); + let currBytes =3D bytes.load(std::sync::atomic= ::Ordering::SeqCst); + let currZeroes =3D zeroes.load(std::sync::atom= ic::Ordering::SeqCst); + //if per !=3D next_per { + if currPer < next_per { + eprintln!("progress {}% (read {} bytes, ze= roes =3D {}% ({} bytes), duration {} sec)", + next_per, currBytes, + currZeroes*100/currBytes, currZeroes= , + start_time.elapsed().as_secs()); + per.store(next_per, std::sync::atomic::Ord= ering::SeqCst); + } + //eprintln!("{} progress LEFT", pos); + locked_progress_clone.store(false, std::sync::= atomic::Ordering::Release); // unlock it + } + //eprintln!("{} END", pos); + Ok(()) + } + ) + ); + =20 + //if futs.len() >=3D 2 {=20 + if futs.len() >=3D 12 { // no performance advantage to use val= ues higher than 1 here, if we don't read with >=3D 2 threads + while let Some(response) =3D futs.next().await { + //eprintln!("Emptying queue. Current length: {}", futs= .len()); + if let Err(e) =3D response { + eprintln!("Error during await: {}", e); + } } - bytes +=3D raw_data.len(); } - if verbose { - let next_per =3D ((pos+1)*100)/index.index_count(); - if per !=3D next_per { - eprintln!("progress {}% (read {} bytes, zeroes =3D {}%= ({} bytes), duration {} sec)", - next_per, bytes, - zeroes*100/bytes, zeroes, - start_time.elapsed().as_secs()); - per =3D next_per; - } + } + eprintln!("END: push tasks"); + eprintln!("BEGIN: await remaining"); + // Wait for the remaining to finish. + while let Some(response) =3D futs.next().await { + eprintln!("Emptying queue. Current length: {}", futs.len()); + if let Err(e) =3D response { + eprintln!("Error during await: {}", e); } } - + //if let Err(e) =3D futures::future::try_join_all(tokio_handles).a= wait { + // eprintln!("Error during await: {}", e); + //} + eprintln!("END: await remaining"); + =20 + let bytes =3D bytes.load(std::sync::atomic::Ordering::SeqCst); + let zeroes =3D zeroes.load(std::sync::atomic::Ordering::SeqCst); let end_time =3D std::time::Instant::now(); let elapsed =3D end_time.duration_since(start_time); - eprintln!("restore image complete (bytes=3D{}, duration=3D{:.2}s, = speed=3D{:.2}MB/s)", + eprintln!("restore image complete (bytes=3D{}, zeroes=3D{}, durati= on=3D{:.2}s, speed=3D{:.2}MB/s)", bytes, + zeroes, elapsed.as_secs_f64(), bytes as f64/(1024.0*1024.0*elapsed.as_secs_f64()) ); Full Log of original restore: new volume ID is 'local-zfs:vm-100-disk-0' restore proxmox backup image: /usr/bin/pbs-restore --repository root@pam@lo= calhost:datastore vm/100/2020-12-01T12:34:43Z drive-scsi0.img.fidx /dev/zvo= l/rpool/data/vm-100-disk-0 --verbose --format raw --skip-zero connecting to repository 'root@pam@localhost:datastore' open block backend for target '/dev/zvol/rpool/data/vm-100-disk-0' starting to restore snapshot 'vm/100/2020-12-01T12:34:43Z' download and verify backup index progress 1% (read 343932928 bytes, zeroes =3D 35% (121634816 bytes), durati= on 2 sec) progress 2% (read 687865856 bytes, zeroes =3D 17% (121634816 bytes), durati= on 5 sec) progress 3% (read 1031798784 bytes, zeroes =3D 12% (125829120 bytes), durat= ion 11 sec) progress 4% (read 1375731712 bytes, zeroes =3D 9% (130023424 bytes), durati= on 18 sec) progress 5% (read 1719664640 bytes, zeroes =3D 7% (130023424 bytes), durati= on 24 sec) progress 6% (read 2063597568 bytes, zeroes =3D 6% (130023424 bytes), durati= on 31 sec) progress 7% (read 2407530496 bytes, zeroes =3D 10% (255852544 bytes), durat= ion 36 sec) progress 8% (read 2751463424 bytes, zeroes =3D 9% (255852544 bytes), durati= on 42 sec) progress 9% (read 3095396352 bytes, zeroes =3D 8% (255852544 bytes), durati= on 49 sec) progress 10% (read 3439329280 bytes, zeroes =3D 7% (260046848 bytes), durat= ion 55 sec) progress 11% (read 3783262208 bytes, zeroes =3D 6% (264241152 bytes), durat= ion 62 sec) progress 12% (read 4127195136 bytes, zeroes =3D 6% (264241152 bytes), durat= ion 69 sec) progress 13% (read 4466933760 bytes, zeroes =3D 8% (390070272 bytes), durat= ion 73 sec) progress 14% (read 4810866688 bytes, zeroes =3D 8% (390070272 bytes), durat= ion 80 sec) progress 15% (read 5154799616 bytes, zeroes =3D 7% (390070272 bytes), durat= ion 86 sec) progress 16% (read 5498732544 bytes, zeroes =3D 7% (390070272 bytes), durat= ion 93 sec) progress 17% (read 5842665472 bytes, zeroes =3D 6% (390070272 bytes), durat= ion 99 sec) progress 18% (read 6186598400 bytes, zeroes =3D 6% (390070272 bytes), durat= ion 106 sec) progress 19% (read 6530531328 bytes, zeroes =3D 7% (469762048 bytes), durat= ion 112 sec) progress 20% (read 6874464256 bytes, zeroes =3D 7% (515899392 bytes), durat= ion 117 sec) progress 21% (read 7218397184 bytes, zeroes =3D 7% (515899392 bytes), durat= ion 124 sec) progress 22% (read 7562330112 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 130 sec) progress 23% (read 7906263040 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 137 sec) progress 24% (read 8250195968 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 144 sec) progress 25% (read 8589934592 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 150 sec) progress 26% (read 8933867520 bytes, zeroes =3D 7% (641728512 bytes), durat= ion 155 sec) progress 27% (read 9277800448 bytes, zeroes =3D 6% (641728512 bytes), durat= ion 161 sec) progress 28% (read 9621733376 bytes, zeroes =3D 6% (641728512 bytes), durat= ion 168 sec) progress 29% (read 9965666304 bytes, zeroes =3D 6% (641728512 bytes), durat= ion 175 sec) progress 30% (read 10309599232 bytes, zeroes =3D 6% (641728512 bytes), dura= tion 182 sec) progress 31% (read 10653532160 bytes, zeroes =3D 6% (641728512 bytes), dura= tion 189 sec) progress 32% (read 10997465088 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 192 sec) progress 33% (read 11341398016 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 200 sec) progress 34% (read 11685330944 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 206 sec) progress 35% (read 12029263872 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 213 sec) progress 36% (read 12373196800 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 220 sec) progress 37% (read 12717129728 bytes, zeroes =3D 8% (1098907648 bytes), dur= ation 220 sec) progress 38% (read 13056868352 bytes, zeroes =3D 10% (1426063360 bytes), du= ration 220 sec) progress 39% (read 13400801280 bytes, zeroes =3D 13% (1769996288 bytes), du= ration 220 sec) progress 40% (read 13744734208 bytes, zeroes =3D 15% (2113929216 bytes), du= ration 220 sec) progress 41% (read 14088667136 bytes, zeroes =3D 17% (2457862144 bytes), du= ration 220 sec) progress 42% (read 14432600064 bytes, zeroes =3D 19% (2801795072 bytes), du= ration 220 sec) progress 43% (read 14776532992 bytes, zeroes =3D 21% (3145728000 bytes), du= ration 220 sec) progress 44% (read 15120465920 bytes, zeroes =3D 23% (3485466624 bytes), du= ration 220 sec) progress 45% (read 15464398848 bytes, zeroes =3D 23% (3690987520 bytes), du= ration 221 sec) progress 46% (read 15808331776 bytes, zeroes =3D 25% (4034920448 bytes), du= ration 221 sec) progress 47% (read 16152264704 bytes, zeroes =3D 27% (4378853376 bytes), du= ration 221 sec) progress 48% (read 16496197632 bytes, zeroes =3D 28% (4722786304 bytes), du= ration 221 sec) progress 49% (read 16840130560 bytes, zeroes =3D 30% (5062524928 bytes), du= ration 221 sec) progress 50% (read 17179869184 bytes, zeroes =3D 31% (5402263552 bytes), du= ration 221 sec) progress 51% (read 17523802112 bytes, zeroes =3D 32% (5725224960 bytes), du= ration 221 sec) progress 52% (read 17867735040 bytes, zeroes =3D 33% (6069157888 bytes), du= ration 221 sec) progress 53% (read 18211667968 bytes, zeroes =3D 35% (6413090816 bytes), du= ration 221 sec) progress 54% (read 18555600896 bytes, zeroes =3D 36% (6757023744 bytes), du= ration 221 sec) progress 55% (read 18899533824 bytes, zeroes =3D 37% (7100956672 bytes), du= ration 221 sec) progress 56% (read 19243466752 bytes, zeroes =3D 38% (7444889600 bytes), du= ration 221 sec) progress 57% (read 19587399680 bytes, zeroes =3D 39% (7776239616 bytes), du= ration 222 sec) progress 58% (read 19931332608 bytes, zeroes =3D 40% (8120172544 bytes), du= ration 222 sec) progress 59% (read 20275265536 bytes, zeroes =3D 41% (8464105472 bytes), du= ration 222 sec) progress 60% (read 20619198464 bytes, zeroes =3D 42% (8808038400 bytes), du= ration 222 sec) progress 61% (read 20963131392 bytes, zeroes =3D 43% (9151971328 bytes), du= ration 222 sec) progress 62% (read 21307064320 bytes, zeroes =3D 44% (9495904256 bytes), du= ration 222 sec) progress 63% (read 21646802944 bytes, zeroes =3D 45% (9789505536 bytes), du= ration 223 sec) progress 64% (read 21990735872 bytes, zeroes =3D 45% (10003415040 bytes), d= uration 224 sec) progress 65% (read 22334668800 bytes, zeroes =3D 46% (10347347968 bytes), d= uration 224 sec) progress 66% (read 22678601728 bytes, zeroes =3D 47% (10691280896 bytes), d= uration 224 sec) progress 67% (read 23022534656 bytes, zeroes =3D 47% (11035213824 bytes), d= uration 224 sec) progress 68% (read 23366467584 bytes, zeroes =3D 48% (11379146752 bytes), d= uration 224 sec) progress 69% (read 23710400512 bytes, zeroes =3D 49% (11714691072 bytes), d= uration 224 sec) progress 70% (read 24054333440 bytes, zeroes =3D 50% (12050235392 bytes), d= uration 224 sec) progress 71% (read 24398266368 bytes, zeroes =3D 50% (12394168320 bytes), d= uration 224 sec) progress 72% (read 24742199296 bytes, zeroes =3D 51% (12738101248 bytes), d= uration 224 sec) progress 73% (read 25086132224 bytes, zeroes =3D 52% (13082034176 bytes), d= uration 224 sec) progress 74% (read 25430065152 bytes, zeroes =3D 52% (13425967104 bytes), d= uration 224 sec) progress 75% (read 25769803776 bytes, zeroes =3D 53% (13765705728 bytes), d= uration 224 sec) progress 76% (read 26113736704 bytes, zeroes =3D 53% (14101250048 bytes), d= uration 224 sec) progress 77% (read 26457669632 bytes, zeroes =3D 54% (14445182976 bytes), d= uration 224 sec) progress 78% (read 26801602560 bytes, zeroes =3D 55% (14789115904 bytes), d= uration 224 sec) progress 79% (read 27145535488 bytes, zeroes =3D 55% (15133048832 bytes), d= uration 224 sec) progress 80% (read 27489468416 bytes, zeroes =3D 56% (15476981760 bytes), d= uration 224 sec) progress 81% (read 27833401344 bytes, zeroes =3D 56% (15820914688 bytes), d= uration 224 sec) progress 82% (read 28177334272 bytes, zeroes =3D 57% (16156459008 bytes), d= uration 224 sec) progress 83% (read 28521267200 bytes, zeroes =3D 57% (16500391936 bytes), d= uration 224 sec) progress 84% (read 28865200128 bytes, zeroes =3D 58% (16844324864 bytes), d= uration 224 sec) progress 85% (read 29209133056 bytes, zeroes =3D 58% (17188257792 bytes), d= uration 224 sec) progress 86% (read 29553065984 bytes, zeroes =3D 59% (17532190720 bytes), d= uration 224 sec) progress 87% (read 29896998912 bytes, zeroes =3D 59% (17876123648 bytes), d= uration 224 sec) progress 88% (read 30236737536 bytes, zeroes =3D 60% (18203279360 bytes), d= uration 224 sec) progress 89% (read 30580670464 bytes, zeroes =3D 60% (18547212288 bytes), d= uration 224 sec) progress 90% (read 30924603392 bytes, zeroes =3D 61% (18891145216 bytes), d= uration 224 sec) progress 91% (read 31268536320 bytes, zeroes =3D 61% (19235078144 bytes), d= uration 224 sec) progress 92% (read 31612469248 bytes, zeroes =3D 61% (19579011072 bytes), d= uration 224 sec) progress 93% (read 31956402176 bytes, zeroes =3D 62% (19922944000 bytes), d= uration 224 sec) progress 94% (read 32300335104 bytes, zeroes =3D 62% (20262682624 bytes), d= uration 224 sec) progress 95% (read 32644268032 bytes, zeroes =3D 63% (20606615552 bytes), d= uration 224 sec) progress 96% (read 32988200960 bytes, zeroes =3D 63% (20950548480 bytes), d= uration 224 sec) progress 97% (read 33332133888 bytes, zeroes =3D 63% (21294481408 bytes), d= uration 224 sec) progress 98% (read 33676066816 bytes, zeroes =3D 64% (21638414336 bytes), d= uration 224 sec) progress 99% (read 34019999744 bytes, zeroes =3D 64% (21982347264 bytes), d= uration 224 sec) progress 100% (read 34359738368 bytes, zeroes =3D 64% (22322085888 bytes), = duration 224 sec) restore image complete (bytes=3D34359738368, duration=3D224.78s, speed=3D14= 5.78MB/s) rescan volumes... TASK OK Full log of restore Using 12 futures, 12 core_threads, 24 max_threads: new volume ID is 'local-zfs:vm-100-disk-0' restore proxmox backup image: /usr/bin/pbs-restore --repository root@pam@lo= calhost:datastore vm/100/2020-12-01T12:34:43Z drive-scsi0.img.fidx /dev/zvo= l/rpool/data/vm-100-disk-0 --verbose --format raw --skip-zero connecting to repository 'root@pam@localhost:datastore' open block backend for target '/dev/zvol/rpool/data/vm-100-disk-0' starting to restore snapshot 'vm/100/2020-12-01T12:34:43Z' download and verify backup index index_count =3D 8192, index_chunk_size: 4194304 BEGIN: push and await tasks progress 1% (read 327155712 bytes, zeroes =3D 37% (121634816 bytes), durati= on 0 sec) progress 2% (read 675282944 bytes, zeroes =3D 18% (121634816 bytes), durati= on 2 sec) progress 3% (read 1010827264 bytes, zeroes =3D 12% (125829120 bytes), durat= ion 6 sec) progress 4% (read 1367343104 bytes, zeroes =3D 9% (130023424 bytes), durati= on 11 sec) progress 5% (read 1715470336 bytes, zeroes =3D 7% (130023424 bytes), durati= on 15 sec) progress 6% (read 2038431744 bytes, zeroes =3D 6% (130023424 bytes), durati= on 20 sec) progress 7% (read 2382364672 bytes, zeroes =3D 10% (255852544 bytes), durat= ion 23 sec) progress 8% (read 2726297600 bytes, zeroes =3D 9% (255852544 bytes), durati= on 28 sec) progress 9% (read 3074424832 bytes, zeroes =3D 8% (255852544 bytes), durati= on 31 sec) progress 10% (read 3430940672 bytes, zeroes =3D 7% (260046848 bytes), durat= ion 36 sec) progress 11% (read 3779067904 bytes, zeroes =3D 6% (264241152 bytes), durat= ion 41 sec) progress 12% (read 4097835008 bytes, zeroes =3D 6% (264241152 bytes), durat= ion 45 sec) progress 13% (read 4462739456 bytes, zeroes =3D 8% (390070272 bytes), durat= ion 47 sec) progress 14% (read 4785700864 bytes, zeroes =3D 8% (390070272 bytes), durat= ion 52 sec) progress 15% (read 5154799616 bytes, zeroes =3D 7% (390070272 bytes), durat= ion 56 sec) progress 16% (read 5494538240 bytes, zeroes =3D 7% (390070272 bytes), durat= ion 61 sec) progress 17% (read 5842665472 bytes, zeroes =3D 6% (390070272 bytes), durat= ion 65 sec) progress 18% (read 6161432576 bytes, zeroes =3D 6% (390070272 bytes), durat= ion 69 sec) progress 19% (read 6530531328 bytes, zeroes =3D 7% (469762048 bytes), durat= ion 73 sec) progress 20% (read 6853492736 bytes, zeroes =3D 7% (515899392 bytes), durat= ion 76 sec) progress 21% (read 7205814272 bytes, zeroes =3D 7% (515899392 bytes), durat= ion 81 sec) progress 22% (read 7558135808 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 86 sec) progress 23% (read 7906263040 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 90 sec) progress 24% (read 8237613056 bytes, zeroes =3D 6% (515899392 bytes), durat= ion 95 sec) progress 25% (read 8560574464 bytes, zeroes =3D 6% (520093696 bytes), durat= ion 99 sec) progress 26% (read 8917090304 bytes, zeroes =3D 7% (641728512 bytes), durat= ion 101 sec) progress 27% (read 9265217536 bytes, zeroes =3D 6% (641728512 bytes), durat= ion 106 sec) progress 28% (read 9617539072 bytes, zeroes =3D 6% (641728512 bytes), durat= ion 110 sec) progress 29% (read 9940500480 bytes, zeroes =3D 6% (641728512 bytes), durat= ion 115 sec) progress 30% (read 10280239104 bytes, zeroes =3D 6% (641728512 bytes), dura= tion 119 sec) progress 31% (read 10624172032 bytes, zeroes =3D 6% (641728512 bytes), dura= tion 124 sec) progress 32% (read 10976493568 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 127 sec) progress 33% (read 11333009408 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 132 sec) progress 34% (read 11681136640 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 136 sec) progress 35% (read 12012486656 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 141 sec) progress 36% (read 12356419584 bytes, zeroes =3D 6% (767557632 bytes), dura= tion 145 sec) progress 37% (read 12717129728 bytes, zeroes =3D 8% (1098907648 bytes), dur= ation 145 sec) progress 38% (read 13056868352 bytes, zeroes =3D 10% (1426063360 bytes), du= ration 145 sec) progress 39% (read 13400801280 bytes, zeroes =3D 13% (1769996288 bytes), du= ration 145 sec) progress 40% (read 13744734208 bytes, zeroes =3D 15% (2113929216 bytes), du= ration 145 sec) progress 41% (read 14088667136 bytes, zeroes =3D 17% (2457862144 bytes), du= ration 145 sec) progress 42% (read 14432600064 bytes, zeroes =3D 19% (2801795072 bytes), du= ration 145 sec) progress 43% (read 14772338688 bytes, zeroes =3D 21% (3141533696 bytes), du= ration 145 sec) progress 44% (read 15120465920 bytes, zeroes =3D 23% (3485466624 bytes), du= ration 145 sec) progress 45% (read 15464398848 bytes, zeroes =3D 23% (3690987520 bytes), du= ration 146 sec) progress 46% (read 15808331776 bytes, zeroes =3D 25% (4034920448 bytes), du= ration 146 sec) progress 47% (read 16148070400 bytes, zeroes =3D 27% (4374659072 bytes), du= ration 146 sec) progress 48% (read 16496197632 bytes, zeroes =3D 28% (4722786304 bytes), du= ration 146 sec) progress 49% (read 16835936256 bytes, zeroes =3D 30% (5058330624 bytes), du= ration 146 sec) progress 50% (read 17175674880 bytes, zeroes =3D 31% (5398069248 bytes), du= ration 146 sec) progress 51% (read 17523802112 bytes, zeroes =3D 32% (5725224960 bytes), du= ration 146 sec) progress 52% (read 17867735040 bytes, zeroes =3D 33% (6069157888 bytes), du= ration 146 sec) progress 53% (read 18186502144 bytes, zeroes =3D 35% (6387924992 bytes), du= ration 147 sec) progress 54% (read 18555600896 bytes, zeroes =3D 36% (6757023744 bytes), du= ration 147 sec) progress 55% (read 18899533824 bytes, zeroes =3D 37% (7100956672 bytes), du= ration 147 sec) progress 56% (read 19243466752 bytes, zeroes =3D 38% (7444889600 bytes), du= ration 147 sec) progress 57% (read 19587399680 bytes, zeroes =3D 39% (7776239616 bytes), du= ration 147 sec) progress 58% (read 19931332608 bytes, zeroes =3D 40% (8120172544 bytes), du= ration 147 sec) progress 59% (read 20275265536 bytes, zeroes =3D 41% (8464105472 bytes), du= ration 147 sec) progress 60% (read 20619198464 bytes, zeroes =3D 42% (8808038400 bytes), du= ration 147 sec) progress 61% (read 20963131392 bytes, zeroes =3D 43% (9151971328 bytes), du= ration 147 sec) progress 62% (read 21307064320 bytes, zeroes =3D 44% (9495904256 bytes), du= ration 147 sec) progress 63% (read 21646802944 bytes, zeroes =3D 45% (9789505536 bytes), du= ration 147 sec) progress 64% (read 21990735872 bytes, zeroes =3D 45% (10003415040 bytes), d= uration 149 sec) progress 65% (read 22334668800 bytes, zeroes =3D 46% (10347347968 bytes), d= uration 149 sec) progress 66% (read 22678601728 bytes, zeroes =3D 47% (10691280896 bytes), d= uration 149 sec) progress 67% (read 23022534656 bytes, zeroes =3D 47% (11035213824 bytes), d= uration 149 sec) progress 68% (read 23366467584 bytes, zeroes =3D 48% (11379146752 bytes), d= uration 149 sec) progress 69% (read 23710400512 bytes, zeroes =3D 49% (11714691072 bytes), d= uration 149 sec) progress 70% (read 24050139136 bytes, zeroes =3D 50% (12046041088 bytes), d= uration 149 sec) progress 71% (read 24398266368 bytes, zeroes =3D 50% (12394168320 bytes), d= uration 149 sec) progress 72% (read 24742199296 bytes, zeroes =3D 51% (12738101248 bytes), d= uration 149 sec) progress 73% (read 25086132224 bytes, zeroes =3D 52% (13082034176 bytes), d= uration 149 sec) progress 74% (read 25430065152 bytes, zeroes =3D 52% (13425967104 bytes), d= uration 149 sec) progress 75% (read 25769803776 bytes, zeroes =3D 53% (13765705728 bytes), d= uration 149 sec) progress 76% (read 26113736704 bytes, zeroes =3D 53% (14101250048 bytes), d= uration 149 sec) progress 77% (read 26457669632 bytes, zeroes =3D 54% (14445182976 bytes), d= uration 149 sec) progress 78% (read 26797408256 bytes, zeroes =3D 55% (14784921600 bytes), d= uration 149 sec) progress 79% (read 27145535488 bytes, zeroes =3D 55% (15133048832 bytes), d= uration 149 sec) progress 80% (read 27489468416 bytes, zeroes =3D 56% (15476981760 bytes), d= uration 150 sec) progress 81% (read 27804041216 bytes, zeroes =3D 56% (15791554560 bytes), d= uration 150 sec) progress 82% (read 28177334272 bytes, zeroes =3D 57% (16156459008 bytes), d= uration 150 sec) progress 83% (read 28504489984 bytes, zeroes =3D 57% (16483614720 bytes), d= uration 150 sec) progress 84% (read 28865200128 bytes, zeroes =3D 58% (16844324864 bytes), d= uration 150 sec) progress 85% (read 29209133056 bytes, zeroes =3D 58% (17188257792 bytes), d= uration 150 sec) progress 86% (read 29553065984 bytes, zeroes =3D 59% (17532190720 bytes), d= uration 150 sec) progress 87% (read 29876027392 bytes, zeroes =3D 59% (17855152128 bytes), d= uration 151 sec) progress 88% (read 30232543232 bytes, zeroes =3D 60% (18203279360 bytes), d= uration 151 sec) progress 89% (read 30576476160 bytes, zeroes =3D 60% (18543017984 bytes), d= uration 151 sec) progress 90% (read 30924603392 bytes, zeroes =3D 61% (18891145216 bytes), d= uration 151 sec) progress 91% (read 31264342016 bytes, zeroes =3D 61% (19230883840 bytes), d= uration 152 sec) progress 92% (read 31612469248 bytes, zeroes =3D 61% (19579011072 bytes), d= uration 152 sec) progress 93% (read 31956402176 bytes, zeroes =3D 62% (19922944000 bytes), d= uration 152 sec) progress 94% (read 32296140800 bytes, zeroes =3D 62% (20258488320 bytes), d= uration 152 sec) progress 95% (read 32644268032 bytes, zeroes =3D 63% (20606615552 bytes), d= uration 152 sec) progress 96% (read 32988200960 bytes, zeroes =3D 63% (20950548480 bytes), d= uration 152 sec) progress 97% (read 33332133888 bytes, zeroes =3D 63% (21294481408 bytes), d= uration 152 sec) progress 98% (read 33676066816 bytes, zeroes =3D 64% (21638414336 bytes), d= uration 152 sec) progress 99% (read 34003222528 bytes, zeroes =3D 64% (21965570048 bytes), d= uration 152 sec) END: push tasks BEGIN: await remaining Emptying queue. Current length: 7 Emptying queue. Current length: 6 Emptying queue. Current length: 5 Emptying queue. Current length: 4 Emptying queue. Current length: 3 Emptying queue. Current length: 2 progress 100% (read 34359738368 bytes, zeroes =3D 64% (22322085888 bytes), = duration 153 sec) Emptying queue. Current length: 1 Emptying queue. Current length: 0 END: await remaining restore image complete (bytes=3D34359738368, zeroes=3D22322085888, duration= =3D153.04s, speed=3D214.11MB/s) rescan volumes... TASK OK