Libertem: Severe performance regression (at least) in K2IS since 0.5.0
The K2IS dataset reached the same pixel-per-pixel performance as raw in the past. On Moellenstedt this was about 5 GPix/s. The 202 GB dataset /cachedata/users/clausen/K2IS01_vacuum_.gtg should fit the file system cache on Moellenstedt, and if not, the SSD RAID it is stored on can deliver 6 GB/s. That means this file should be analyzed in just about half a minute under ideal conditions.
A ring analysis on this file in a notebook took way over 10 minutes in tests using the current master at this time and the state of #812. I aborted the tests because they took too long.
The 0.5.0 release version reached the expected performance:
# First run
CPU times: user 9.5 s, sys: 1.06 s, total: 10.6 s
Wall time: 35.7 s
# Second run
CPU times: user 8.21 s, sys: 1.01 s, total: 9.22 s
Wall time: 35.1 s
Zipped test notebook
k2is-performance.zip
Other file types were not tested yet.
We should discuss if we fast-track at least a prototype version of #198 for the 0.6 release since we have to get a handle on this before the release one way or another, in particular testing all the file formats we support, GPU processing, and a good sample of analyses.
Edit: ...plus, we still have #798 on our list for 0.6 which falls in the same category.
uellue
All 18 comments
I'm not sure if this is helpful, but I'm getting distributed.worker - WARNING - Memory use is high but worker has no data to store to disk. Perhaps some other process is leaking memory? Process memory: 1.82 GB -- Worker memory limit: 2.09 GB when I run an analysis on a K2IS dataset.
AnandBaburajan
on 12 Jun 2020
@AnandBaburajan Thx! Not sure if it has the same root cause as the performance regression, but definitely something that shouldn't happen. How do you reproduce it?
uellue
on 12 Jun 2020
@AnandBaburajan Thx! Not sure if it has the same root cause as the performance regression, but definitely something that shouldn't happen. How do you reproduce it?
I ran a disk analysis through the GUI (current master) on a ~ 8 GB K2IS dataset.
AnandBaburajan
on 12 Jun 2020
Memory use is high but worker has no data to store to disk
This can possibly also be caused by the way dask measures memory usage - IIRC it's possible that memory mapped files are included in that memory usage figure. Generally, the K2IS dataset is very sensitive to memory management issues, so it's possible we are not re-using a buffer somewhere, and generate lots of garbage, which is something that has caused regressions before. As there have been quite a few changes since 0.5 (example: what tiling scheme is negotiated?), we'll have to profile to be sure.
sk1p
on 12 Jun 2020
So, one of the performance-significant changes since the release was b0ea77accd4c04cb6b691430ad46bc957222f2a4, which, for each tile, checks for discrepancies when getting a contiguous view for a tile. We do O(N*M) work for this consistency check, where N is the number of tiles and M is the number of slices in the tiling scheme. This is a significant amount, in a micro benchmark with M=255 items in the cache, the disjoint check costs almost 3ms on my system:
s1 = Slice(
origin=(0, 0, 0),
shape=Shape((255, 255, 255), sig_dims=2),
)
s2 = Slice(
origin=(512, 0, 0),
shape=Shape((255, 255, 255), sig_dims=2),
)
d1 = {
Slice(
origin=(i, 0, 0),
shape=Shape((255, 255, 255), sig_dims=2)
): True
for i in range(255)
}
(so, for 25600 tiles that means we have about 75s overhead, which feels about right)
This is how the line profile looks like for a real UDF run on K2IS data:
Profile
Timer unit: 1e-06 s
Total time: 75.4251 s
File: /home/alex/source/LiberTEM/src/libertem/common/buffers.py
Function: get_contiguous_view_for_tile at line 391
Line # Hits Time Per Hit % Time Line Contents
==============================================================
391 def get_contiguous_view_for_tile(self, partition, tile):
392 '''
393 Make a cached contiguous copy of the view for a single tile
394 if necessary.
395
396 Currently this is only necessary for :code:`kind="sig"` buffers.
397 Use :meth:`flush` to write back the cache.
398
399 Boundary condition: :code:`tile.tile_slice.get(sig_only=True)`
400 does not overlap for different tiles while the cache is active,
401 i.e. the tiles follow LiberTEM slicing for
402 :meth:`libertem.udf.base.UDFTileMixing.process_tile()`.
403
404 .. versionadded:: 0.5.0
405
406 Returns
407 -------
408
409 view : np.ndarray
410 View into data or contiguous copy if necessary
411
412 '''
413 76128 58382.0 0.8 0.1 if self._kind == "sig":
414 50752 1328605.0 26.2 1.8 key = tile.tile_slice.discard_nav()
415 50752 291846.0 5.8 0.4 if key in self._contiguous_cache:
416 33792 191819.0 5.7 0.3 view = self._contiguous_cache[key]
417 else:
418 16960 328092.0 19.3 0.4 sl = key.get(sig_only=True)
419 16960 33627.0 2.0 0.0 view = self._data[sl]
420 # See if the signal dimension can be flattened
421 # https://docs.scipy.org/doc/numpy/reference/generated/numpy.reshape.html
422 16960 17629.0 1.0 0.0 if not view.flags.c_contiguous:
423 16960 71122690.0 4193.6 94.3 assert disjoint(key, self._contiguous_cache.keys())
424 # print(len(self._contiguous_cache.keys()))
425 16960 728652.0 43.0 1.0 view = view.copy()
426 16960 80213.0 4.7 0.1 self._contiguous_cache[key] = view
427 50752 25777.0 0.5 0.0 return view
428 else:
429 25376 1217754.0 48.0 1.6 return self.get_view_for_tile(partition, tile)
Total time: 83.4469 s
File: /home/alex/source/LiberTEM/src/libertem/udf/base.py
Function: _run_tile at line 1002
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1002 def _run_tile(self, partition, udfs, tile, device_tile):
1003 50752 59749.0 1.2 0.1 for udf in udfs:
1004 25376 48071.0 1.9 0.1 method = udf.get_method()
1005 25376 19689.0 0.8 0.0 if method == 'tile':
1006 25376 76127752.0 3000.0 91.2 udf.set_contiguous_views_for_tile(partition, tile)
1007 25376 81645.0 3.2 0.1 udf.set_slice(tile.tile_slice)
1008 25376 7109999.0 280.2 8.5 udf.process_tile(device_tile)
1009 elif method == 'frame':
1010 tile_slice = tile.tile_slice
1011 for frame_idx, frame in enumerate(device_tile):
1012 frame_slice = Slice(
1013 origin=(tile_slice.origin[0] + frame_idx,) + tile_slice.origin[1:],
1014 shape=Shape((1,) + tuple(tile_slice.shape)[1:],
1015 sig_dims=tile_slice.shape.sig.dims),
1016 )
1017 udf.set_slice(frame_slice)
1018 udf.set_views_for_frame(partition, tile, frame_idx)
1019 udf.process_frame(frame)
1020 elif method == 'partition':
1021 udf.set_views_for_tile(partition, tile)
1022 udf.set_slice(partition.slice)
1023 udf.process_partition(device_tile)
Total time: 90.0483 s
File: /home/alex/source/LiberTEM/src/libertem/udf/base.py
Function: _run_udfs at line 1025
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1025 def _run_udfs(self, numpy_udfs, cupy_udfs, partition, tiling_scheme, roi, dtype):
1026 # FIXME pass information on target location (numpy or cupy)
1027 # to dataset so that is can already move it there.
1028 # In the future, it might even decode data on the device instead of CPU
1029 68 123.0 1.8 0.0 tiles = partition.get_tiles(
1030 34 30.0 0.9 0.0 tiling_scheme=tiling_scheme,
1031 34 18.0 0.5 0.0 roi=roi, dest_dtype=dtype,
1032 )
1033
1034 34 19.0 0.6 0.0 if cupy_udfs:
1035 xp = cupy_udfs[0].xp
1036
1037 34 22.0 0.6 0.0 run_tile = self._run_tile
1038 25410 6378304.0 251.0 7.1 for tile in tiles:
1039 25376 83655019.0 3296.6 92.9 run_tile(partition, numpy_udfs, tile, tile)
1040 25376 14779.0 0.6 0.0 if cupy_udfs:
1041 # Work-around, should come from dataset later
1042 device_tile = xp.asanyarray(tile)
1043 run_tile(partition, cupy_udfs, tile, device_tile)
See also 06e769705beeb4cf32c8def001d187fc220eb1c5 where I extracted _run_tile as a function, so it can be more easily profiled.
I didn't spend time to fix this yet, but I know that the intersection function used in disjoint is not optimized yet, but also, the disjoint-check could be optimized with some cleverness (merging slices and whatnot) so it doesn't stay O(N*M).
sk1p
on 16 Jun 2020
For comparison, here is a profile with the assertion disabled:
Profile
Timer unit: 1e-06 s
Total time: 4.15365 s
File: /home/alex/source/LiberTEM/src/libertem/common/buffers.py
Function: get_contiguous_view_for_tile at line 391
Line # Hits Time Per Hit % Time Line Contents
==============================================================
391 def get_contiguous_view_for_tile(self, partition, tile):
392 '''
393 Make a cached contiguous copy of the view for a single tile
394 if necessary.
395
396 Currently this is only necessary for :code:`kind="sig"` buffers.
397 Use :meth:`flush` to write back the cache.
398
399 Boundary condition: :code:`tile.tile_slice.get(sig_only=True)`
400 does not overlap for different tiles while the cache is active,
401 i.e. the tiles follow LiberTEM slicing for
402 :meth:`libertem.udf.base.UDFTileMixing.process_tile()`.
403
404 .. versionadded:: 0.5.0
405
406 Returns
407 -------
408
409 view : np.ndarray
410 View into data or contiguous copy if necessary
411
412 '''
413 76128 55704.0 0.7 1.3 if self._kind == "sig":
414 50752 1258557.0 24.8 30.3 key = tile.tile_slice.discard_nav()
415 50752 284037.0 5.6 6.8 if key in self._contiguous_cache:
416 33792 182468.0 5.4 4.4 view = self._contiguous_cache[key]
417 else:
418 16960 319264.0 18.8 7.7 sl = key.get(sig_only=True)
419 16960 30148.0 1.8 0.7 view = self._data[sl]
420 # See if the signal dimension can be flattened
421 # https://docs.scipy.org/doc/numpy/reference/generated/numpy.reshape.html
422 16960 15807.0 0.9 0.4 if not view.flags.c_contiguous:
423 # assert disjoint(key, self._contiguous_cache.keys())
424 # print(len(self._contiguous_cache.keys()))
425 16960 714963.0 42.2 17.2 view = view.copy()
426 16960 75181.0 4.4 1.8 self._contiguous_cache[key] = view
427 50752 23007.0 0.5 0.6 return view
428 else:
429 25376 1194516.0 47.1 28.8 return self.get_view_for_tile(partition, tile)
Total time: 12.0559 s
File: /home/alex/source/LiberTEM/src/libertem/udf/base.py
Function: _run_tile at line 1002
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1002 def _run_tile(self, partition, udfs, tile, device_tile):
1003 50752 56377.0 1.1 0.5 for udf in udfs:
1004 25376 46404.0 1.8 0.4 method = udf.get_method()
1005 25376 17834.0 0.7 0.1 if method == 'tile':
1006 25376 4835850.0 190.6 40.1 udf.set_contiguous_views_for_tile(partition, tile)
1007 25376 78917.0 3.1 0.7 udf.set_slice(tile.tile_slice)
1008 25376 7020525.0 276.7 58.2 udf.process_tile(device_tile)
1009 elif method == 'frame':
1010 tile_slice = tile.tile_slice
1011 for frame_idx, frame in enumerate(device_tile):
1012 frame_slice = Slice(
1013 origin=(tile_slice.origin[0] + frame_idx,) + tile_slice.origin[1:],
1014 shape=Shape((1,) + tuple(tile_slice.shape)[1:],
1015 sig_dims=tile_slice.shape.sig.dims),
1016 )
1017 udf.set_slice(frame_slice)
1018 udf.set_views_for_frame(partition, tile, frame_idx)
1019 udf.process_frame(frame)
1020 elif method == 'partition':
1021 udf.set_views_for_tile(partition, tile)
1022 udf.set_slice(partition.slice)
1023 udf.process_partition(device_tile)
Total time: 18.7698 s
File: /home/alex/source/LiberTEM/src/libertem/udf/base.py
Function: _run_udfs at line 1025
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1025 def _run_udfs(self, numpy_udfs, cupy_udfs, partition, tiling_scheme, roi, dtype):
1026 # FIXME pass information on target location (numpy or cupy)
1027 # to dataset so that is can already move it there.
1028 # In the future, it might even decode data on the device instead of CPU
1029 68 118.0 1.7 0.0 tiles = partition.get_tiles(
1030 34 22.0 0.6 0.0 tiling_scheme=tiling_scheme,
1031 34 12.0 0.4 0.0 roi=roi, dest_dtype=dtype,
1032 )
1033
1034 34 16.0 0.5 0.0 if cupy_udfs:
1035 xp = cupy_udfs[0].xp
1036
1037 34 19.0 0.6 0.0 run_tile = self._run_tile
1038 25410 6504033.0 256.0 34.7 for tile in tiles:
1039 25376 12252781.0 482.8 65.3 run_tile(partition, numpy_udfs, tile, tile)
1040 25376 12773.0 0.5 0.1 if cupy_udfs:
1041 # Work-around, should come from dataset later
1042 device_tile = xp.asanyarray(tile)
1043 run_tile(partition, cupy_udfs, tile, device_tile)
We can see that this is already much faster, but there still is potential for optimization.
sk1p
on 16 Jun 2020
@sk1p Thx for the analysis! Fixing the test for disjointness did improve the benchmark I am working on, but it doesn't seem to fix the original issue.
Judging from this profile from inline executor and with a ROI limiting to the first row of scan pixels, it is the generator returned by get_tiles() that spends most of the time.
If it was the buffer, the time would be spent in run_tile, specifically udf.set_contiguous_views_for_tile() like you have shown above.
Profile
Timer unit: 1e-06 s
Total time: 26.0237 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/udf/base.py
Function: _run_udfs at line 981
Line # Hits Time Per Hit % Time Line Contents
==============================================================
981 def _run_udfs(self, numpy_udfs, cupy_udfs, partition, tiling_scheme, roi, dtype):
982 9 13.0 1.4 0.0 def run_tile(udfs, tile, device_tile):
983 for udf in udfs:
984 method = udf.get_method()
985 if method == 'tile':
986 udf.set_contiguous_views_for_tile(partition, tile)
987 udf.set_slice(tile.tile_slice)
988 udf.process_tile(device_tile)
989 elif method == 'frame':
990 tile_slice = tile.tile_slice
991 for frame_idx, frame in enumerate(device_tile):
992 frame_slice = Slice(
993 origin=(tile_slice.origin[0] + frame_idx,) + tile_slice.origin[1:],
994 shape=Shape((1,) + tuple(tile_slice.shape)[1:],
995 sig_dims=tile_slice.shape.sig.dims),
996 )
997 udf.set_slice(frame_slice)
998 udf.set_views_for_frame(partition, tile, frame_idx)
999 udf.process_frame(frame)
1000 elif method == 'partition':
1001 udf.set_views_for_tile(partition, tile)
1002 udf.set_slice(partition.slice)
1003 udf.process_partition(device_tile)
1004
1005 # FIXME pass information on target location (numpy or cupy)
1006 # to dataset so that is can already move it there.
1007 # In the future, it might even decode data on the device instead of CPU
1008 9 11.0 1.2 0.0 tiles = partition.get_tiles(
1009 9 9.0 1.0 0.0 tiling_scheme=tiling_scheme,
1010 9 11.0 1.2 0.0 roi=roi, dest_dtype=dtype,
1011 )
1012
1013 9 8.0 0.9 0.0 if cupy_udfs:
1014 xp = cupy_udfs[0].xp
1015
1016 6409 23804838.0 3714.3 91.5 for tile in tiles:
1017 6400 2207666.0 344.9 8.5 run_tile(numpy_udfs, tile, tile)
1018 6400 11110.0 1.7 0.0 if cupy_udfs:
1019 # Work-around, should come from dataset later
1020 device_tile = xp.asanyarray(tile)
1021 run_tile(cupy_udfs, tile, device_tile)
Total time: 26.1989 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/udf/base.py
Function: run_for_partition at line 1068
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1068 def run_for_partition(self, partition: Partition, roi, corrections):
1069 9 50927.0 5658.6 0.2 with set_num_threads(1):
1070 9 10.0 1.1 0.0 try:
1071 9 8.0 0.9 0.0 previous_id = None
1072 9 223.0 24.8 0.0 device_class = get_device_class()
1073 # numpy_udfs and cupy_udfs contain references to the objects in
1074 # self._udfs
1075 9 142.0 15.8 0.0 numpy_udfs, cupy_udfs = self._udf_lists(device_class)
1076 # Will only be populated if actually on CUDA worker
1077 # and any UDF supports 'cupy' (and not 'cuda')
1078 9 6.0 0.7 0.0 if cupy_udfs:
1079 # Avoid importing if not used
1080 import cupy
1081 device = get_use_cuda()
1082 previous_id = cupy.cuda.Device().id
1083 cupy.cuda.Device(device).use()
1084 9 7.0 0.8 0.0 (meta, tiling_scheme, dtype) = self._init_udfs(
1085 9 89347.0 9927.4 0.3 numpy_udfs, cupy_udfs, partition, roi, corrections, device_class
1086 )
1087 # print("UDF TilingScheme: %r" % tiling_scheme.shape)
1088 9 26.0 2.9 0.0 partition.set_corrections(corrections)
1089 9 26056884.0 2895209.3 99.5 self._run_udfs(numpy_udfs, cupy_udfs, partition, tiling_scheme, roi, dtype)
1090 9 655.0 72.8 0.0 self._wrapup_udfs(numpy_udfs, cupy_udfs, partition)
1091 finally:
1092 9 10.0 1.1 0.0 if previous_id is not None:
1093 cupy.cuda.Device(previous_id).use()
1094 # Make sure results are in the same order as the UDFs
1095 9 696.0 77.3 0.0 return tuple(udf.results for udf in self._udfs)
In #820 I made some changes that facilitate profiling. Here's the full picture. I couldn't follow the code further down since I didn't quite understand where io_backend.get_tiles() comes from.
Profile
Timer unit: 1e-06 s
Total time: 0.670488 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/common/buffers.py
Function: get_view_for_tile at line 361
Line # Hits Time Per Hit % Time Line Contents
==============================================================
361 def get_view_for_tile(self, partition, tile):
362 """
363 get a view for a single tile in a partition-sized buffer
364 (partition-sized here means the reduced result for a whole partition,
365 not the partition itself!)
366 """
367 6400 142390.0 22.2 21.2 assert partition.shape.dims == partition.shape.sig.dims + 1
368 6400 6278.0 1.0 0.9 if self._contiguous_cache:
369 raise RuntimeError("Cache is not empty, has to be flushed")
370 6400 190273.0 29.7 28.4 if self.roi_is_zero:
371 raise ValueError("cannot get view for tile with zero ROI")
372 6400 6835.0 1.1 1.0 if self._kind == "sig":
373 return self._data[tile.tile_slice.get(sig_only=True)]
374 6400 4973.0 0.8 0.7 elif self._kind == "nav":
375 6400 239959.0 37.5 35.8 partition_slice = self._slice_for_partition(partition)
376 6400 5384.0 0.8 0.8 tile_slice = tile.tile_slice
377 6400 4897.0 0.8 0.7 if self._data_coords_global:
378 offset = 0
379 else:
380 6400 5361.0 0.8 0.8 offset = partition_slice.origin[0]
381 6400 9374.0 1.5 1.4 result_start = tile_slice.origin[0] - offset
382 6400 20819.0 3.3 3.1 result_stop = result_start + tile_slice.shape[0]
383 # shape: (1,) + self._extra_shape
384 6400 25324.0 4.0 3.8 if len(self._extra_shape) + tile_slice.shape[0] > 1:
385 6400 8621.0 1.3 1.3 return self._data[result_start:result_stop]
386 else:
387 return self._data[result_start:result_stop, np.newaxis]
388 elif self._kind == "single":
389 return self._data
Total time: 0.764737 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/common/buffers.py
Function: get_contiguous_view_for_tile at line 391
Line # Hits Time Per Hit % Time Line Contents
==============================================================
391 def get_contiguous_view_for_tile(self, partition, tile):
392 '''
393 Make a cached contiguous copy of the view for a single tile
394 if necessary.
395
396 Currently this is only necessary for :code:`kind="sig"` buffers.
397 Use :meth:`flush` to write back the cache.
398
399 Boundary condition: :code:`tile.tile_slice.get(sig_only=True)`
400 does not overlap for different tiles while the cache is active,
401 i.e. the tiles follow LiberTEM slicing for
402 :meth:`libertem.udf.base.UDFTileMixing.process_tile()`.
403
404 .. versionadded:: 0.5.0
405
406 Returns
407 -------
408
409 view : np.ndarray
410 View into data or contiguous copy if necessary
411
412 '''
413 6400 6300.0 1.0 0.8 if self._kind == "sig":
414 key = tile.tile_slice.discard_nav()
415 if key in self._contiguous_cache:
416 view = self._contiguous_cache[key]
417 else:
418 sl = key.get(sig_only=True)
419 view = self._data[sl]
420 # See if the signal dimension can be flattened
421 # https://docs.scipy.org/doc/numpy/reference/generated/numpy.reshape.html
422 if not view.flags.c_contiguous:
423 assert disjoint(key, self._contiguous_cache.keys())
424 view = view.copy()
425 self._contiguous_cache[key] = view
426 return view
427 else:
428 6400 758437.0 118.5 99.2 return self.get_view_for_tile(partition, tile)
Total time: 1.9e-05 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/common/buffers.py
Function: flush at line 430
Line # Hits Time Per Hit % Time Line Contents
==============================================================
430 def flush(self):
431 '''
432 Write back any cached contiguous copies
433
434 .. versionadded:: 0.5.0
435 '''
436 9 12.0 1.3 63.2 if self._kind == "sig":
437 for key, view in self._contiguous_cache.items():
438 sl = key.get(sig_only=True)
439 self._data[sl] = view
440 self._contiguous_cache = dict()
441 else:
442 # Cache flushing not implemented for other kinds
443 9 7.0 0.8 36.8 assert not self._contiguous_cache
Total time: 22.0707 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/io/dataset/base/partition.py
Function: get_tiles at line 216
Line # Hits Time Per Hit % Time Line Contents
==============================================================
216 def get_tiles(self, tiling_scheme, dest_dtype="float32", roi=None):
217 """
218 Return a generator over all DataTiles contained in this Partition.
219
220 Note
221 ----
222 The DataSet may reuse the internal buffer of a tile, so you should
223 directly process the tile and not accumulate a number of tiles and then work
224 on them.
225
226 Parameters
227 ----------
228
229 tiling_scheme
230 According to this scheme the data will be tiled
231
232 dest_dtype : numpy dtype
233 convert data to this dtype when reading
234
235 roi : numpy.ndarray
236 Boolean array that matches the dataset navigation shape to limit the region to work on.
237 With a ROI, we yield tiles from a "compressed" navigation axis, relative to
238 the beginning of the dataset. Compressed means, only frames that have a 1
239 in the ROI are considered, and the resulting tile slices are from a coordinate
240 system that has the shape `(np.count_nonzero(roi),)`.
241 """
242 9 15.0 1.7 0.0 dest_dtype = np.dtype(dest_dtype)
243 9 91.0 10.1 0.0 self.validate_tiling_scheme(tiling_scheme)
244 9 33695.0 3743.9 0.2 read_ranges = self._get_read_ranges(tiling_scheme, roi)
245 9 147.0 16.3 0.0 io_backend = self._get_io_backend()
246
247 9 7.0 0.8 0.0 yield from io_backend.get_tiles(
248 9 6.0 0.7 0.0 tiling_scheme=tiling_scheme, fileset=self._fileset,
249 9 4.0 0.4 0.0 read_ranges=read_ranges, roi=roi,
250 9 22036743.0 2448527.0 99.8 native_dtype=self.meta.raw_dtype, read_dtype=dest_dtype
251 )
Total time: 2.48326 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/udf/base.py
Function: _run_tile at line 981
Line # Hits Time Per Hit % Time Line Contents
==============================================================
981 def _run_tile(self, udfs, partition, tile, device_tile):
982 12800 16589.0 1.3 0.7 for udf in udfs:
983 6400 16580.0 2.6 0.7 method = udf.get_method()
984 6400 5256.0 0.8 0.2 if method == 'tile':
985 6400 904318.0 141.3 36.4 udf.set_contiguous_views_for_tile(partition, tile)
986 6400 25122.0 3.9 1.0 udf.set_slice(tile.tile_slice)
987 6400 1515399.0 236.8 61.0 udf.process_tile(device_tile)
988 elif method == 'frame':
989 tile_slice = tile.tile_slice
990 for frame_idx, frame in enumerate(device_tile):
991 frame_slice = Slice(
992 origin=(tile_slice.origin[0] + frame_idx,) + tile_slice.origin[1:],
993 shape=Shape((1,) + tuple(tile_slice.shape)[1:],
994 sig_dims=tile_slice.shape.sig.dims),
995 )
996 udf.set_slice(frame_slice)
997 udf.set_views_for_frame(partition, tile, frame_idx)
998 udf.process_frame(frame)
999 elif method == 'partition':
1000 udf.set_views_for_tile(partition, tile)
1001 udf.set_slice(partition.slice)
1002 udf.process_partition(device_tile)
Total time: 26.6178 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/udf/base.py
Function: _run_udfs at line 1004
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1004 def _run_udfs(self, numpy_udfs, cupy_udfs, partition, tiling_scheme, roi, dtype):
1005 # FIXME pass information on target location (numpy or cupy)
1006 # to dataset so that is can already move it there.
1007 # In the future, it might even decode data on the device instead of CPU
1008 9 11.0 1.2 0.0 tiles = partition.get_tiles(
1009 9 2.0 0.2 0.0 tiling_scheme=tiling_scheme,
1010 9 7.0 0.8 0.0 roi=roi, dest_dtype=dtype,
1011 )
1012
1013 9 6.0 0.7 0.0 if cupy_udfs:
1014 xp = cupy_udfs[0].xp
1015
1016 6409 24063887.0 3754.7 90.4 for tile in tiles:
1017 6400 2548839.0 398.3 9.6 self._run_tile(numpy_udfs, partition, tile, tile)
1018 6400 5085.0 0.8 0.0 if cupy_udfs:
1019 # Work-around, should come from dataset later
1020 device_tile = xp.asanyarray(tile)
1021 self._run_tile(cupy_udfs, partition, tile, device_tile)
Total time: 26.7814 s
File: /cachedata/users/weber/LiberTEM-uellue/src/libertem/udf/base.py
Function: run_for_partition at line 1068
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1068 def run_for_partition(self, partition: Partition, roi, corrections):
1069 9 52988.0 5887.6 0.2 with set_num_threads(1):
1070 9 13.0 1.4 0.0 try:
1071 9 8.0 0.9 0.0 previous_id = None
1072 9 245.0 27.2 0.0 device_class = get_device_class()
1073 # numpy_udfs and cupy_udfs contain references to the objects in
1074 # self._udfs
1075 9 143.0 15.9 0.0 numpy_udfs, cupy_udfs = self._udf_lists(device_class)
1076 # Will only be populated if actually on CUDA worker
1077 # and any UDF supports 'cupy' (and not 'cuda')
1078 9 7.0 0.8 0.0 if cupy_udfs:
1079 # Avoid importing if not used
1080 import cupy
1081 device = get_use_cuda()
1082 previous_id = cupy.cuda.Device().id
1083 cupy.cuda.Device(device).use()
1084 9 12.0 1.3 0.0 (meta, tiling_scheme, dtype) = self._init_udfs(
1085 9 92557.0 10284.1 0.3 numpy_udfs, cupy_udfs, partition, roi, corrections, device_class
1086 )
1087 # print("UDF TilingScheme: %r" % tiling_scheme.shape)
1088 9 29.0 3.2 0.0 partition.set_corrections(corrections)
1089 9 26633957.0 2959328.6 99.4 self._run_udfs(numpy_udfs, cupy_udfs, partition, tiling_scheme, roi, dtype)
1090 9 682.0 75.8 0.0 self._wrapup_udfs(numpy_udfs, cupy_udfs, partition)
1091 finally:
1092 9 9.0 1.0 0.0 if previous_id is not None:
1093 cupy.cuda.Device(previous_id).use()
1094 # Make sure results are in the same order as the UDFs
1095 9 758.0 84.2 0.0 return tuple(udf.results for udf in self._udfs)
it doesn't seem to fix the original issue
How long does the test using the 202 GB file take now? I locally tested with a smaller file, and got about 14s using v0.5, and 17s using your branch, doing a warm-up run to get the numba compilation excluded.
I couldn't follow the code further down since I didn't quite understand where io_backend.get_tiles() comes from.
I can continue there, if you like - I'll need to work on that code anyways for #798
sk1p
on 18 Jun 2020
I'm using the StdDev UDF for these tests, btw. And for comparison: this took about 46s with master. So I would say the main part is fixed, and there is some remaining work for generally getting back to 0.5 perf.
sk1p
on 18 Jun 2020
How long does the test using the 202 GB file take now?
I'm running it now. It was significantly longer than the 35 s from before.
uellue
on 18 Jun 2020
As discussed, we can first merge #819 to add the benchmarking suite and the first part of the regression fix, then I can take over for the second part regarding general I/O performance, JIT caching etc.
sk1p
on 18 Jun 2020
distributed.worker - WARNING - Memory use is high but worker has no data to store to disk. Perhaps some other process is leaking memory? Process memory: 1.82 GB -- Worker memory limit: 2.09 GB
After updating to current master, I'm getting the same message with a 4 GB MIB dataset (with 256 files), a 8 GB SEQ one and the K2IS one, but not with smaller datasets. The workers running analysis on MIB and K2IS restarted a few times and eventually stopped before completing the analysis. The analysis on SEQ ran successfully.
My PC specs FYI: 8 GB RAM and 512 GB SSD running Windows
AnandBaburajan
on 29 Jun 2020
After updating to current master, I'm getting the same message with a 4 GB
MIBdataset (with 256 files), a 8 GBSEQone and theK2ISone, but not with smaller datasets. The workers running analysis onMIBandK2ISrestarted a few times and eventually stopped before completing the analysis. The analysis onSEQran successfully.
Interesting.
- Did you try to work on a subset of data and see if that works, using
roi? - Did you measure, for example using system tools, how much memory the worker processes are actually taking up? Is that memory really used by the process itself (
RESin Linux top-like tools), or is it virtual memory used bymmaping of files (VIRTin top-like tools)? - Can you see if you can disable the memory usage limits of the dask workers, if that fixes things?
I suspect the new I/O subsystem actually also takes up a bit more RAM, and I'll have to re-think some approaches there anyways because of the slow-ish numba-compilation and caching. For K2IS there may be some intermediate data structures which scale with the number of blocks per partition, I'll try to eliminate those completely.
sk1p
on 29 Jun 2020
Did you try to work on a subset of data and see if that works, using
roi?
No errors when a small ROI is set.
Did you measure, for example using system tools, how much memory the worker processes are actually taking up? Is that memory really used by the process itself (
RESin Linux top-like tools), or is it virtual memory used bymmaping of files (VIRTin top-like tools)?
Sorry, I'm not able to figure out how to find the memory consumption of each worker process on my Windows PC, and the only Linux PC I've access to is at my institute.
Can you see if you can disable the memory usage limits of the dask workers, if that fixes things?
Yes, disabling the limits did fix the errors.
I suspect the new I/O subsystem actually also takes up a bit more RAM
I think so too because manually setting ds.set_num_cores(len(workers)) to a bit bigger number resulted in no errors at all.
AnandBaburajan
on 30 Jun 2020
Interesting, thanks for trying this out!
Sorry, I'm not able to figure out how to find the memory consumption of each worker process on my Windows PC, and the only Linux PC I've access to is at my institute.
No worries - if you look at the total memory consumption, does it come close to the limits of your system?
Can you see if you can disable the memory usage limits of the dask workers, if that fixes things?
Yes, disabling the limits did fix the errors.
I suspect the new I/O subsystem actually also takes up a bit more RAM
I think so too because manually setting
ds.set_num_cores(len(workers))to a bit bigger number resulted in no errors at all.
Thanks again for trying this, this is helpful! I'll see if I can come find the root cause and a fix.
Another question: if you try with the stable LiberTEM version (0.5.0), is the behavior the same?
sk1p
on 1 Jul 2020
if you look at the total memory consumption, does it come close to the limits of your system?
A disk analysis on the 8 GB K2IS dataset uses around 1.2 GB and before #819 was merged, it took around 1.8 GB.
if you try with the stable LiberTEM version (0.5.0), is the behavior the same?
I tried and found no issues with 0.5.0.
AnandBaburajan
on 1 Jul 2020
I now have a handle on the originally reported performance regression - this was mostly an issue that using posix_fadvise caused massive performance issues on the large K2IS files. It's also possible that this is an issue with older Linux kernel versions, but I can't properly test this on my local workstation right now, which have a newer kernel (5.7.0 vs the old 3.10.0 on our CentOS server). I'm now working on refactoring the I/O backend to allow influencing the backend "from the outside", which will first make benchmarking a lot easier, and then also allow specifying an alternative backend. For solving the K2IS case, I'm going to disable fadvise in all cases by default - we will have to live with a slight regression with the (MIB, HDD, Linux) configuration for now (users can re-enable fadvise in that case to re-gain a bit...).
Then, I'll implement a buffering backend (with a large-ish buffer of something like 16MiB by default - let's benchmark that) and select that on windows by default, to fix #838. This buffered reader will also make it very easy to implement direct I/O for most of the data set implementations, which is a plus
The memory usage issue is another problem - this will have to be handled separately. I've created #894 for this.
sk1p
on 5 Nov 2020
Related issues
unsimulatable
路
9Comments
uellue
路
4Comments
uellue
路
9Comments
uellue
路
7Comments
sk1p
路
7Comments
Most helpful comment
This can possibly also be caused by the way dask measures memory usage - IIRC it's possible that memory mapped files are included in that memory usage figure. Generally, the K2IS dataset is very sensitive to memory management issues, so it's possible we are not re-using a buffer somewhere, and generate lots of garbage, which is something that has caused regressions before. As there have been quite a few changes since 0.5 (example: what tiling scheme is negotiated?), we'll have to profile to be sure.