Support PPE profiling for FileCache / MultiprocessFileCache

[KantaTamura]

This PR resolves the FileCache / MultiprocessFileCache task in #258

Note

preload() and preserve() are excluded from profiling because they are pre-processing and post-processing and have nothing to do with the I/O being executed.

Sample program to check tracing

import json
import pytorch_pfn_extras as ppe

from pfio.cache import FileCache, MultiprocessFileCache


def filecache():
    tracer = ppe.profiler.get_tracer()
    tracer.clear()

    cache = FileCache(1, dir="./tmp", do_pickle=True, trace=True)
    cache.put(0, b"foo")
    assert b"foo" == cache.get(0)

    dict = ppe.profiler.get_tracer().state_dict()
    keys = [event["name"] for event in json.loads(dict['_event_list'])]

    print(keys)

    w = ppe.writing.SimpleWriter(out_dir="")
    tracer.initialize_writer("trace_filecache.json", w)
    tracer.flush("trace_filecache.json", w)


def multiprocess_filecache():
    tracer = ppe.profiler.get_tracer()
    tracer.clear()

    cache = MultiprocessFileCache(1, dir="./tmp", do_pickle=True, trace=True)
    cache.put(0, b"foo")
    assert b"foo" == cache.get(0)

    dict = ppe.profiler.get_tracer().state_dict()
    keys = [event["name"] for event in json.loads(dict['_event_list'])]

    print(keys)

    w = ppe.writing.SimpleWriter(out_dir="")
    tracer.initialize_writer("trace_multiprocess_filecache.json", w)
    tracer.flush("trace_multiprocess_filecache.json", w)


filecache()
multiprocess_filecache()

output

['pfio.cache.file:put:lock', 'pfio.cache.file:put', 'pfio.cache.file:get:lock', 'pfio.cache.file:get']
['pfio.cache.multiprocessfile:put:lock-99', 'pfio.cache.multiprocessfile:put', 'pfio.cache.multiprocessfile:get:lock-99', 'pfio.cache.multiprocessfile:get']

rendering of the output json file with chrome://tracing is shown below

• trace_filecache.json
  

• trace_multiprocess_filecache.json
  

[k5342]

Test codes are LGTM, but I have more suggestions for records.

[k5342]

I think it's better we add more records to track the actual I/O operation here because under get:lock issues one rdlock and two pread operations.

[k5342]

ditto as above

[k5342]

ah, we need to track this read call as well

[k5342]

Like file_cache, we'd like to track I/O-related and lock operations separately. Separating them will be useful for diagnosing whether I/O or just lock wait is long.

[k5342]

LGTM