Skip to content

Commit 26b3023

Browse files
Fallen-BreathFallen-Breath
committed
debug logging optimization with debug level check guard
1 parent 59b726e commit 26b3023

5 files changed

Lines changed: 60 additions & 40 deletions

File tree

‎prime_backup/action/helpers/blob_allocator.py‎

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -238,16 +238,21 @@ def get_or_create_blob(self, src_path: Path, st: os.stat_result) -> BlobLookupRo
238238
for i in range(_BLOB_FILE_CHANGED_RETRY_COUNT):
239239
retry_cnt = i + 1 # [1, n]
240240
is_last_attempt = retry_cnt == _BLOB_FILE_CHANGED_RETRY_COUNT
241-
if i > 0:
241+
if i > 0 and self.logger.isEnabledFor(logging.DEBUG):
242242
self.logger.debug('Try to create blob {} (attempt {} / {})'.format(src_path_str, retry_cnt, _BLOB_FILE_CHANGED_RETRY_COUNT))
243243
try:
244244
blob = yield from self.__try_get_or_create_blob_once(src_path, src_path_md5, st, last_chance=is_last_attempt, is_mutating_file=is_mutating_file)
245245
self.__ctx.remember_blob(blob)
246246
return GetOrCreateBlobResult(blob, st)
247247
except BlobFileChanged:
248-
(self.logger.warning if is_last_attempt else self.logger.debug)('Blob {} stat has changed, has someone modified it? {} (attempt {} / {})'.format(
249-
src_path_str, 'No more retry' if is_last_attempt else 'Retrying', retry_cnt, _BLOB_FILE_CHANGED_RETRY_COUNT
250-
))
248+
if is_last_attempt:
249+
self.logger.warning('Blob {} stat has changed, has someone modified it? {} (attempt {} / {})'.format(
250+
src_path_str, 'No more retry', retry_cnt, _BLOB_FILE_CHANGED_RETRY_COUNT
251+
))
252+
elif self.logger.isEnabledFor(logging.DEBUG):
253+
self.logger.debug('Blob {} stat has changed, has someone modified it? {} (attempt {} / {})'.format(
254+
src_path_str, 'Retrying', retry_cnt, _BLOB_FILE_CHANGED_RETRY_COUNT
255+
))
251256
st = src_path.lstat()
252257
except Exception as e:
253258
self.logger.error('Create blob for file {} failed (attempt {} / {}): {}'.format(src_path_str, retry_cnt, _BLOB_FILE_CHANGED_RETRY_COUNT, e))

‎prime_backup/action/helpers/blob_creator_chunked.py‎

Lines changed: 34 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,7 @@
1-
from __future__ import annotations
2-
31
import contextlib
42
import dataclasses
53
import enum
4+
import logging
65
import os
76
import time
87
from concurrent.futures import Future
@@ -109,12 +108,13 @@ def get_or_create(self) -> BlobLookupRoutine[schema.Blob]:
109108

110109
write_result = self.__create_missing_chunks(actual_path_to_read, snapshot, known_db_chunks)
111110

112-
self.logger.debug('Chunked file {} in {:.2f}s, compressed size {}/{}, chunk count: {} (+{}, {:.1f}%)'.format(
113-
src_path_str, time.time() - process_start_time,
114-
write_result.stored_size_sum, write_result.raw_size_sum,
115-
len(write_result.offset_to_db_chunk), len(write_result.new_db_chunks),
116-
100.0 * len(write_result.new_db_chunks) / max(1, len(write_result.offset_to_db_chunk)),
117-
))
111+
if self.logger.isEnabledFor(logging.DEBUG):
112+
self.logger.debug('Chunked file {} in {:.2f}s, compressed size {}/{}, chunk count: {} (+{}, {:.1f}%)'.format(
113+
src_path_str, time.time() - process_start_time,
114+
write_result.stored_size_sum, write_result.raw_size_sum,
115+
len(write_result.offset_to_db_chunk), len(write_result.new_db_chunks),
116+
100.0 * len(write_result.new_db_chunks) / max(1, len(write_result.offset_to_db_chunk)),
117+
))
118118
if (
119119
len(write_result.new_db_chunks) >= max(5000, int(write_result.unique_chunk_count * 0.6)) and
120120
self.ctx.file_lookup.previous_backup_has_chunked_file(self.args.src_path)
@@ -138,9 +138,10 @@ def __select_plan(self) -> _ChunkedBlobPlan:
138138
policy = _ChunkedBlobCreatePolicy.default
139139
pre_cal_result = self.ctx.file_lookup.pop_pre_calc_result(self.args.src_path)
140140
if pre_cal_result is not None and (self.args.st.st_size != pre_cal_result.size or pre_cal_result.should_be_chunked is False):
141-
self.logger.debug('Drop pre cal result for path {} due to stat mismatched, st.st_size {}, pre_cal_result {}'.format(
142-
self.args.src_path, self.args.st.st_size, pre_cal_result.simple_repr(),
143-
))
141+
if self.logger.isEnabledFor(logging.DEBUG):
142+
self.logger.debug('Drop pre cal result for path {} due to stat mismatched, st.st_size {}, pre_cal_result {}'.format(
143+
self.args.src_path, self.args.st.st_size, pre_cal_result.simple_repr(),
144+
))
144145
pre_cal_result = None
145146
return _ChunkedBlobPlan(policy, pre_cal_result)
146147

@@ -163,17 +164,20 @@ def __load_or_cut_chunks(self, actual_path_to_read: Path, pre_cal_result: Option
163164
if pre_cal_result.chunks is not None:
164165
chunks = pre_cal_result.chunks
165166
blob_size = pre_cal_result.size
166-
self.logger.debug('Cut and hashed file {} with size {} into {} chunks using {} (precalc)'.format(
167-
src_path_str, ByteCount(blob_size).auto_str(), len(chunks), self.args.chunk_method.name,
168-
))
167+
if self.logger.isEnabledFor(logging.DEBUG):
168+
self.logger.debug('Cut and hashed file {} with size {} into {} chunks using {} (precalc)'.format(
169+
src_path_str, ByteCount(blob_size).auto_str(), len(chunks), self.args.chunk_method.name,
170+
))
169171
if (cache := (yield from self.query_cached_blob(pre_calc_blob_hash))) is not None:
170-
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, pre_calc_blob_hash))
172+
if self.logger.isEnabledFor(logging.DEBUG):
173+
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, pre_calc_blob_hash))
171174
return cache
172175
return _ChunkedBlobSnapshot(chunks, pre_calc_blob_hash, blob_size)
173176

174177
if pre_calc_blob_hash is not None:
175178
if (cache := (yield from self.query_cached_blob(pre_calc_blob_hash))) is not None:
176-
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, pre_calc_blob_hash))
179+
if self.logger.isEnabledFor(logging.DEBUG):
180+
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, pre_calc_blob_hash))
177181
return cache
178182

179183
if (
@@ -188,12 +192,14 @@ def __load_or_cut_chunks(self, actual_path_to_read: Path, pre_cal_result: Option
188192
if sah.size != self.args.st.st_size:
189193
self.log_and_raise_blob_file_changed('Blob size mismatch, previous: {}, current: {}'.format(self.args.st.st_size, sah.size), self.args.last_chance)
190194
pre_calc_blob_hash = sah.hash
191-
self.logger.debug('Hashed stat unchanged chunked file {} with size {} in {:.2f}s ({}/s)'.format(
192-
src_path_str, ByteCount(sah.size).auto_str(), hash_cost(),
193-
ByteCount(sah.size / hash_cost() if hash_cost() > 0 else 0).auto_str(),
194-
))
195+
if self.logger.isEnabledFor(logging.DEBUG):
196+
self.logger.debug('Hashed stat unchanged chunked file {} with size {} in {:.2f}s ({}/s)'.format(
197+
src_path_str, ByteCount(sah.size).auto_str(), hash_cost(),
198+
ByteCount(sah.size / hash_cost() if hash_cost() > 0 else 0).auto_str(),
199+
))
195200
if (cache := (yield from self.query_cached_blob(pre_calc_blob_hash))) is not None:
196-
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, pre_calc_blob_hash))
201+
if self.logger.isEnabledFor(logging.DEBUG):
202+
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, pre_calc_blob_hash))
197203
return cache
198204

199205
previous_chunks = self.ctx.file_lookup.get_previous_chunks(self.args.src_path) if self.args.chunk_method.needs_previous_chunks() else None
@@ -205,12 +211,14 @@ def __load_or_cut_chunks(self, actual_path_to_read: Path, pre_cal_result: Option
205211
if pre_calc_blob_hash is not None and pre_calc_blob_hash != blob_hash:
206212
self.log_and_raise_blob_file_changed('Blob hash mismatch, pre calc {}, chunked {}'.format(pre_calc_blob_hash, blob_hash), self.args.last_chance)
207213

208-
self.logger.debug('Cut and hashed file {} with size {} into {} chunks using {} in {:.2f}s ({}/s)'.format(
209-
src_path_str, ByteCount(blob_size).auto_str(), len(chunks), self.args.chunk_method.name, chunking_cost(),
210-
ByteCount(blob_size / chunking_cost() if chunking_cost() > 0 else 0).auto_str(),
211-
))
214+
if self.logger.isEnabledFor(logging.DEBUG):
215+
self.logger.debug('Cut and hashed file {} with size {} into {} chunks using {} in {:.2f}s ({}/s)'.format(
216+
src_path_str, ByteCount(blob_size).auto_str(), len(chunks), self.args.chunk_method.name, chunking_cost(),
217+
ByteCount(blob_size / chunking_cost() if chunking_cost() > 0 else 0).auto_str(),
218+
))
212219
if pre_calc_blob_hash is None and (cache := (yield from self.query_cached_blob(blob_hash))) is not None:
213-
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, blob_hash))
220+
if self.logger.isEnabledFor(logging.DEBUG):
221+
self.logger.debug('Chunked file {} (hash {}) already exists in DB'.format(src_path_str, blob_hash))
214222
return cache
215223
return _ChunkedBlobSnapshot(chunks, blob_hash, blob_size)
216224

‎prime_backup/action/helpers/blob_creator_direct.py‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import dataclasses
22
import enum
3+
import logging
34
import os
45
from pathlib import Path
56
from typing import Optional
@@ -146,9 +147,10 @@ def __can_copy_on_write(self, st: os.stat_result, compress_method: CompressMetho
146147
def __get_pre_calc_blob_hash(self) -> Optional[str]:
147148
pre_cal_result: Optional[BlobPrecalculateResult] = self.ctx.file_lookup.pop_pre_calc_result(self.args.src_path)
148149
if pre_cal_result is not None and (self.args.st.st_size != pre_cal_result.size or pre_cal_result.should_be_chunked is True):
149-
self.logger.debug('Drop pre cal result for path {} due to stat mismatched, st.st_size {}, pre_cal_result {}'.format(
150-
self.args.src_path, self.args.st.st_size, pre_cal_result.simple_repr(),
151-
))
150+
if self.logger.isEnabledFor(logging.DEBUG):
151+
self.logger.debug('Drop pre cal result for path {} due to stat mismatched, st.st_size {}, pre_cal_result {}'.format(
152+
self.args.src_path, self.args.st.st_size, pre_cal_result.simple_repr(),
153+
))
152154
pre_cal_result = None
153155
return pre_cal_result.hash if pre_cal_result is not None else None
154156

‎prime_backup/action/helpers/chunk_grouper.py‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -104,7 +104,8 @@ def create_chunk_groups(self, blob: schema.Blob, blob_chunks: Dict[int, schema.C
104104
)
105105

106106
# end
107-
cost_sec = time.time() - start_time
108-
self.logger.debug('blob chunks finalized in {:.2f}s, chunk group count {} (+{})'.format(
109-
cost_sec, len(raw_chunk_groups), len(new_chunk_group_hashes),
110-
))
107+
if self.logger.isEnabledFor(logging.DEBUG):
108+
cost_sec = time.time() - start_time
109+
self.logger.debug('blob chunks finalized in {:.2f}s, chunk group count {} (+{})'.format(
110+
cost_sec, len(raw_chunk_groups), len(new_chunk_group_hashes),
111+
))

‎prime_backup/action/helpers/pack_writer.py‎

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
import dataclasses
2+
import logging
23
import threading
34
from pathlib import Path
45
from typing import BinaryIO, Optional, List
@@ -102,7 +103,8 @@ def __write_dedicated(self, data: bytes) -> PackEntryLocation:
102103
result = dedicated_pack.append_bytes(data)
103104
self.__created_pack_size += len(data)
104105
dedicated_pack.close()
105-
self.logger.debug(f'Wrote dedicated pack id={dedicated_pack.pack.id} file_name={pack_utils.get_pack_file_name(dedicated_pack.pack.id)} size={len(data)}')
106+
if self.logger.isEnabledFor(logging.DEBUG):
107+
self.logger.debug(f'Wrote dedicated pack id={dedicated_pack.pack.id} file_name={pack_utils.get_pack_file_name(dedicated_pack.pack.id)} size={len(data)}')
106108
return result
107109

108110
def __write_dedicated_reader(self, reader: SupportsReadBytes, size: int) -> PackEntryLocation:
@@ -111,7 +113,8 @@ def __write_dedicated_reader(self, reader: SupportsReadBytes, size: int) -> Pack
111113
result = dedicated_pack.append_reader(reader, size)
112114
self.__created_pack_size += size
113115
dedicated_pack.close()
114-
self.logger.debug(f'Wrote dedicated pack id={dedicated_pack.pack.id} file_name={pack_utils.get_pack_file_name(dedicated_pack.pack.id)} size={size}')
116+
if self.logger.isEnabledFor(logging.DEBUG):
117+
self.logger.debug(f'Wrote dedicated pack id={dedicated_pack.pack.id} file_name={pack_utils.get_pack_file_name(dedicated_pack.pack.id)} size={size}')
115118
return result
116119

117120
def __get_active_for_write_no_lock(self) -> _ActivePack:
@@ -157,4 +160,5 @@ def __open_new_active_no_lock(self):
157160

158161
new_pack = self.__create_new_pack_no_lock()
159162
self.__active = new_pack
160-
self.logger.debug(f'Opened new active pack id={new_pack.pack.id} file_name={pack_utils.get_pack_file_name(new_pack.pack.id)}')
163+
if self.logger.isEnabledFor(logging.DEBUG):
164+
self.logger.debug(f'Opened new active pack id={new_pack.pack.id} file_name={pack_utils.get_pack_file_name(new_pack.pack.id)}')

0 commit comments

Comments
 (0)