' + esc(t(label)) + ': ' + esc(t('min')) + ' ' + st.min + ' ms · ' + esc(t('avg')) + ' ' + st.avg + ' ms · ' + esc(t('max')) + ' ' + st.max + ' ms (n=' + st.count + ')
';
+ }
+ }
+ html += rows
+ ? '';
html += '
' + esc(t('FCI hex (raw SELECT response)')) + '
' +
@@ -7778,7 +7879,9 @@ function profilerRenderSnapshotFiles(s) {
html += '
';
}
html += '
';
} else {
@@ -8845,6 +8948,13 @@ const LANG_RU = {
'Verify vs pySim': 'Проверить в pySim',
'Send to Card': 'Отправить на карту',
'Phone simulator': 'Симулятор телефона',
+ 'Files': 'Файлов',
+ 'Records': 'Записей',
+ 'Scan time': 'Время сканирования',
+ 'No timing data': 'Нет данных о времени',
+ 'min': 'мин',
+ 'avg': 'сред',
+ 'max': 'макс',
'Phone': 'Телефон',
'TR Config': 'Конфигурация TR',
'Events that the card monitors (SET UP EVENT LIST):': 'События, отслеживаемые картой (SET UP EVENT LIST):',
diff --git a/frontend/sw.js b/frontend/sw.js
index 95220b3..cf53041 100644
--- a/frontend/sw.js
+++ b/frontend/sw.js
@@ -1,4 +1,4 @@
-const CACHE = 'otaman-v99';
+const CACHE = 'otaman-v100';
const URLS = [
'index.html',
'help.html',
diff --git a/frontend/tests/html.test.js b/frontend/tests/html.test.js
index 70a2143..2cafea1 100644
--- a/frontend/tests/html.test.js
+++ b/frontend/tests/html.test.js
@@ -37,3 +37,7 @@ test('phone simulator has Phone / TR Config pills', () => {
test('scan name input starts scanning on Enter', () => {
assert.match(html, /id="profiler-scan-name"[^>]*onkeydown="profilerScanNameKeydown\(event\)"/);
});
+
+test('snapshot view has a timing summary block', () => {
+ assert.ok(html.includes('id="snapshot-summary"'));
+});
diff --git a/frontend/tests/profiler.test.js b/frontend/tests/profiler.test.js
index 3857ccb..43590ad 100644
--- a/frontend/tests/profiler.test.js
+++ b/frontend/tests/profiler.test.js
@@ -21,7 +21,7 @@ function extractFunc(src, name, asyncFn) {
return (asyncFn ? 'async ' : '') + src.slice(m.index, i + 1);
}
-const FNS = ['profilerNormHex', 'profilerNormHexStrict', 'profilerMatch', 'profilerMatchMin', 'profilerMaskPrefix4', 'profilerFileFields', 'profilerContentKindForFileType', 'profilerEmptyRecordContent', 'profilerValidateProfile', 'profilerCustomNameForPath', 'profilerUpdateRulePath', 'profilerResultAspects', 'profilerAspectSummary', 'profilerNumRanges', 'esc', 'escHtml', 'profilerRawDataCheck', 'profilerRenderReport', 'parseBerLen', 'parseTlvList', 'fcpInt', 'fcpParseTlvs', 'fcpFileDescriptor', 'fcpLifeCycle', 'fcpSfi', 'fcpDo', 'fcpDecode', 'fcpDiffHtml', 'profilerFciPreviewItems', 'profilerUpdateFciPreview', 'profilerUpdateRule', 'profilerFciInput', 'profilerScanToggleAll', 'profilerScanIgnoreAllState', 'swapNibbles', 'decIccid', 'profilerSnapshotIccid', 'profilerValidateSnapshot', 'profilerListSwitch', 'profilerScanRefreshOptions', 'profilerLiveSource', 'profilerSnapshotSource', 'profilerVisibleResults', 'profilerMaskFidForFile', 'profilerRulesFromSnapshot', 'profilerExtraFileResults', 'profilerScanNameKeydown'];
+const FNS = ['profilerNormHex', 'profilerNormHexStrict', 'profilerMatch', 'profilerMatchMin', 'profilerMaskPrefix4', 'profilerFileFields', 'profilerContentKindForFileType', 'profilerEmptyRecordContent', 'profilerValidateProfile', 'profilerCustomNameForPath', 'profilerUpdateRulePath', 'profilerResultAspects', 'profilerAspectSummary', 'profilerNumRanges', 'esc', 'escHtml', 'profilerRawDataCheck', 'profilerRenderReport', 'parseBerLen', 'parseTlvList', 'fcpInt', 'fcpParseTlvs', 'fcpFileDescriptor', 'fcpLifeCycle', 'fcpSfi', 'fcpDo', 'fcpDecode', 'fcpDiffHtml', 'profilerFciPreviewItems', 'profilerUpdateFciPreview', 'profilerUpdateRule', 'profilerFciInput', 'profilerScanToggleAll', 'profilerScanIgnoreAllState', 'swapNibbles', 'decIccid', 'profilerSnapshotIccid', 'profilerValidateSnapshot', 'profilerListSwitch', 'profilerScanRefreshOptions', 'profilerLiveSource', 'profilerSnapshotSource', 'profilerVisibleResults', 'profilerMaskFidForFile', 'profilerRulesFromSnapshot', 'profilerExtraFileResults', 'profilerScanNameKeydown', 'profilerTimingStats', 'profilerTimingAccumulator', 'profilerFormatMs', 'profilerRenderSnapshotSummary'];
let code = '';
for (const f of FNS) code += extractFunc(html, f) + '\n';
code += extractFunc(html, 'profilerBuildFileRule', true) + '\n';
@@ -1130,3 +1130,89 @@ test('profilerScanNameKeydown starts the scan on Enter only', () => {
delete global.document;
delete global.profilerScanStart;
});
+
+// --- snapshot command timings ---
+
+test('profilerTimingStats computes min, max and average', () => {
+ assert.deepStrictEqual(profilerTimingStats([10, 20, 30]), { min: 10, max: 30, avg: 20, count: 3 });
+ assert.deepStrictEqual(profilerTimingStats([7, 7.5, 8]), { min: 7, max: 8, avg: 7.5, count: 3 });
+ assert.strictEqual(profilerTimingStats([]), null);
+ assert.strictEqual(profilerTimingStats(null), null);
+});
+
+test('profilerFormatMs formats milliseconds and seconds', () => {
+ assert.strictEqual(profilerFormatMs(12), '12 ms');
+ assert.strictEqual(profilerFormatMs(999), '999 ms');
+ assert.strictEqual(profilerFormatMs(1500), '1.50 s');
+ assert.strictEqual(profilerFormatMs(null), 'n/a');
+});
+
+test('profilerTimingAccumulator aggregates per command type', () => {
+ const acc = profilerTimingAccumulator();
+ acc.add('select', 10);
+ acc.add('select', 20);
+ acc.add('read_record', 5);
+ acc.add('bogus', 1);
+ assert.deepStrictEqual(acc.stats(), {
+ select: { min: 10, max: 20, avg: 15, count: 2 },
+ read_record: { min: 5, max: 5, avg: 5, count: 1 },
+ });
+});
+
+test('profilerBuildSnapshotFile records per-command timings', async () => {
+ const acc = profilerTimingAccumulator();
+ mockFetch({
+ '/api/select': () => ({ exists: true, name: 'EF.ADN', file_type: 'linear_fixed', file_size: null, record_len: 2, num_of_rec: 2,
+ apdu_times: [{ type: 'select', ms: 5 }, { type: 'select', ms: 7 }] }),
+ '/api/read': () => ({ success: true, file_type: 'linear_fixed', records: [{ num: 1, data: 'AA' }, { num: 2, data: 'BB' }],
+ apdu_times: [{ type: 'select', ms: 4 }, { type: 'read_record', ms: 11 }, { type: 'read_record', ms: 13 }] }),
+ });
+ const file = await profilerBuildSnapshotFile('MF/6F3A', { name: 'EF.ADN' }, acc);
+ assert.deepStrictEqual(file.timing, { select_ms: 12, read_ms: 24 });
+ assert.strictEqual(file.content.records[0].ms, 11);
+ assert.strictEqual(file.content.records[1].ms, 13);
+ const stats = acc.stats();
+ assert.strictEqual(stats.select.count, 2);
+ assert.strictEqual(stats.read_record.count, 2);
+});
+
+test('profilerBuildSnapshotFile without apdu_times has empty timing', async () => {
+ mockFetch({
+ '/api/select': () => ({ exists: true, name: 'EF.ADN', file_type: 'transparent', file_size: 2, record_len: null, num_of_rec: null }),
+ '/api/read': () => ({ success: true, file_type: 'transparent', data: 'AABB' }),
+ });
+ const file = await profilerBuildSnapshotFile('MF/6F3A', { name: 'EF.ADN' }, null);
+ assert.strictEqual(file.timing, null);
+ assert.deepStrictEqual(file.content, { kind: 'transparent', data: 'AABB' });
+});
+
+test('profilerRenderSnapshotSummary shows counts, scan time and stats', () => {
+ global.t = s => s;
+ const snap = {
+ files: [
+ { content: { kind: 'record', records: [{ num: 1, data: 'AA', ms: 5 }, { num: 2, data: 'BB', ms: 7 }] } },
+ { content: { kind: 'transparent', data: 'AA' } },
+ ],
+ timing: {
+ select: { min: 3, max: 9, avg: 6, count: 3 },
+ read_record: { min: 5, max: 7, avg: 6, count: 2 },
+ total_ms: 1500,
+ },
+ };
+ const html = profilerRenderSnapshotSummary(snap);
+ assert.ok(html.includes('Files:
2'), html);
+ assert.ok(html.includes('Records:
2'), html);
+ assert.ok(html.includes('Scan time:
1.50 s'), html);
+ assert.ok(html.includes('Select: min 3 ms'), html);
+ assert.ok(html.includes('Read record: min 5 ms'), html);
+ assert.ok(!html.includes('Read binary'), html);
+ delete global.t;
+});
+
+test('profilerRenderSnapshotSummary notes missing timing data', () => {
+ global.t = s => s;
+ const html = profilerRenderSnapshotSummary({ files: [], timing: undefined });
+ assert.ok(html.includes('Files:
0'), html);
+ assert.ok(html.includes('No timing data'), html);
+ delete global.t;
+});
diff --git a/pysim_otaman_server/server.py b/pysim_otaman_server/server.py
index 084778b..d9d371e 100644
--- a/pysim_otaman_server/server.py
+++ b/pysim_otaman_server/server.py
@@ -57,6 +57,38 @@ def _tlog(msg):
sys.stderr.write('TIMING [+%7.3fs] %s\n' % (time.time() - _T0, msg))
+_APDU_TIMES = []
+_APDU_TIME_COLLECT = False
+
+def _classify_apdu(cmd):
+ """Map a command APDU to a snapshot timing category by instruction byte."""
+ if not cmd or len(cmd) < 4:
+ return None
+ return {'A4': 'select', 'B0': 'read_binary', 'B2': 'read_record'}.get(cmd[2:4].upper())
+
+
+def _collect_apdu_times():
+ """Start collecting per-command times. (Re)attaches our tracer if pySim
+ nulled it (equip does). Callers hold _CARD_LOCK, so collection cannot be
+ interleaved by the background poll thread."""
+ global _APDU_TIME_COLLECT
+ scc = getattr(_server_ref, 'scc', None) if _server_ref else None
+ tp = getattr(scc, '_tp', None) if scc else None
+ if tp is not None and tp.apdu_tracer is None:
+ tp.apdu_tracer = _LoggingApduTracer()
+ _APDU_TIMES.clear()
+ _APDU_TIME_COLLECT = True
+
+
+def _end_apdu_time_collection():
+ """Stop collecting and return the collected [{type, ms}, ...] list."""
+ global _APDU_TIME_COLLECT
+ _APDU_TIME_COLLECT = False
+ times = list(_APDU_TIMES)
+ _APDU_TIMES.clear()
+ return times
+
+
class StderrApduTracer(ApduTracer):
def __init__(self):
super().__init__()
@@ -75,6 +107,10 @@ class StderrApduTracer(ApduTracer):
global _APDU_N
_APDU_N += 1
elapsed = int((time.time() - self._cmd_start) * 1000)
+ if _APDU_TIME_COLLECT:
+ category = _classify_apdu(cmd)
+ if category:
+ _APDU_TIMES.append({'type': category, 'ms': elapsed})
if _TIMING:
msg = 'APDU-TRACE(+%7.3fs #%d, %dms): %s → SW: %s' % (time.time() - _T0, _APDU_N, elapsed, cmd, sw)
else:
@@ -1916,10 +1952,14 @@ class PysimHandler(BaseHTTPRequestHandler):
return
lchan = rs.lchan[0]
try:
- if path:
- _select_path(lchan, path, app)
- else:
- _select_with_parent(lchan, name, parent_sel, app)
+ _collect_apdu_times()
+ try:
+ if path:
+ _select_path(lchan, path, app)
+ else:
+ _select_with_parent(lchan, name, parent_sel, app)
+ finally:
+ apdu_times = _end_apdu_time_collection()
cur = lchan.selected_file
data = {
'name': cur.name if cur else None,
@@ -1929,6 +1969,7 @@ class PysimHandler(BaseHTTPRequestHandler):
'record_len': lchan.selected_file_record_len() if lchan else None,
'num_of_rec': lchan.selected_file_num_of_rec() if lchan else None,
'fci_hex': (lchan.selected_file_fcp_hex or '').upper() if lchan and lchan.selected_file_fcp_hex else None,
+ 'apdu_times': apdu_times,
'exists': True,
}
self._send_json(data)
@@ -1957,28 +1998,32 @@ class PysimHandler(BaseHTTPRequestHandler):
return
lchan = rs.lchan[0]
try:
- sel = fid if fid else name
- if path:
- _select_path(lchan, path, app)
- else:
- _select_with_parent(lchan, sel, parent_sel, app)
- ft = _get_file_type(lchan, lchan.selected_file)
- is_record = ft in ('linear_fixed', 'cyclic')
- if mode == 'decoded':
- cmd = 'read_records_decoded' if is_record else 'read_binary_decoded'
- else:
- cmd = 'read_records' if is_record else 'read_binary'
- out = StringIO()
- old_stdout = app.stdout
- old_stderr = sys.stderr
- app.stdout = out
- sys.stderr = out
+ _collect_apdu_times()
try:
- app.onecmd_plus_hooks(cmd)
- output = _strip_ansi(out.getvalue())
+ sel = fid if fid else name
+ if path:
+ _select_path(lchan, path, app)
+ else:
+ _select_with_parent(lchan, sel, parent_sel, app)
+ ft = _get_file_type(lchan, lchan.selected_file)
+ is_record = ft in ('linear_fixed', 'cyclic')
+ if mode == 'decoded':
+ cmd = 'read_records_decoded' if is_record else 'read_binary_decoded'
+ else:
+ cmd = 'read_records' if is_record else 'read_binary'
+ out = StringIO()
+ old_stdout = app.stdout
+ old_stderr = sys.stderr
+ app.stdout = out
+ sys.stderr = out
+ try:
+ app.onecmd_plus_hooks(cmd)
+ output = _strip_ansi(out.getvalue())
+ finally:
+ app.stdout = old_stdout
+ sys.stderr = old_stderr
finally:
- app.stdout = old_stdout
- sys.stderr = old_stderr
+ apdu_times = _end_apdu_time_collection()
sw_match = re.search(r'SW:\s*(\w+)', output)
err_match = re.search(r'got (\w+)', output)
if err_match:
@@ -1995,18 +2040,18 @@ class PysimHandler(BaseHTTPRequestHandler):
if mode == 'decoded':
try:
parsed = json.loads(clean)
- resp = {'success': True, 'sw': sw, 'file_type': ft, 'decoded': parsed}
+ resp = {'success': True, 'sw': sw, 'file_type': ft, 'decoded': parsed, 'apdu_times': apdu_times}
except json.JSONDecodeError:
- resp = {'success': True, 'sw': sw, 'file_type': ft, 'data': clean}
+ resp = {'success': True, 'sw': sw, 'file_type': ft, 'data': clean, 'apdu_times': apdu_times}
elif is_record:
records = []
for line in clean.split('\n'):
m = re.match(r'^(\d+)\s(.+)', line)
if m:
records.append({'num': int(m.group(1)), 'data': m.group(2)})
- resp = {'success': True, 'sw': sw, 'file_type': ft, 'records': records}
+ resp = {'success': True, 'sw': sw, 'file_type': ft, 'records': records, 'apdu_times': apdu_times}
else:
- resp = {'success': True, 'sw': sw, 'file_type': ft, 'data': clean}
+ resp = {'success': True, 'sw': sw, 'file_type': ft, 'data': clean, 'apdu_times': apdu_times}
self._send_json(resp)
self._log_resp(resp)
except Exception as e:
diff --git a/tests/test_apdu_timing.py b/tests/test_apdu_timing.py
new file mode 100644
index 0000000..1df132e
--- /dev/null
+++ b/tests/test_apdu_timing.py
@@ -0,0 +1,94 @@
+#!/usr/bin/env python3
+"""Tests for per-command APDU timing collection (card snapshot measurements)."""
+
+import sys
+import time
+import types
+import unittest
+from pathlib import Path
+from unittest import mock
+
+PROJECTS = Path(__file__).resolve().parents[2]
+PY_SIM = PROJECTS / 'pysim'
+if str(PY_SIM) not in sys.path:
+ sys.path.insert(0, str(PY_SIM))
+
+import pysim_otaman_server.server as S
+
+
+class TestClassifyApdu(unittest.TestCase):
+ def test_select(self):
+ self.assertEqual(S._classify_apdu('00a40004023f0000'), 'select')
+
+ def test_read_binary(self):
+ self.assertEqual(S._classify_apdu('00b000000a'), 'read_binary')
+
+ def test_read_record(self):
+ self.assertEqual(S._classify_apdu('00b2010428'), 'read_record')
+
+ def test_other_not_classified(self):
+ self.assertIsNone(S._classify_apdu('80f2000c00'))
+
+ def test_short_input(self):
+ self.assertIsNone(S._classify_apdu(''))
+ self.assertIsNone(S._classify_apdu('00'))
+
+
+class TestApduTimeCollection(unittest.TestCase):
+ def setUp(self):
+ self.saved = (S._APDU_TIME_COLLECT, list(S._APDU_TIMES), S._server_ref)
+ S._APDU_TIME_COLLECT = False
+ S._APDU_TIMES.clear()
+ S._server_ref = None
+
+ def tearDown(self):
+ S._APDU_TIME_COLLECT, times, S._server_ref = self.saved
+ S._APDU_TIMES[:] = times
+
+ def test_disabled_does_not_collect(self):
+ tracer = S.StderrApduTracer()
+ with mock.patch.object(S.os, 'write'):
+ tracer.trace_command('00a40004023f0000')
+ tracer.trace_response('00a40004023f0000', '9000', '')
+ self.assertEqual(S._APDU_TIMES, [])
+
+ def test_collects_only_classified_commands_with_ms(self):
+ S._collect_apdu_times()
+ tracer = S.StderrApduTracer()
+ with mock.patch.object(S.os, 'write'):
+ tracer._cmd_start = time.time() - 0.025
+ tracer.trace_response('00a40004023f0000', '9000', '')
+ tracer._cmd_start = time.time() - 0.010
+ tracer.trace_response('00b000000a', '9000', '')
+ tracer._cmd_start = time.time() - 0.005
+ tracer.trace_response('80f2000c00', '9000', '')
+ times = S._end_apdu_time_collection()
+ self.assertEqual([t['type'] for t in times], ['select', 'read_binary'])
+ self.assertGreaterEqual(times[0]['ms'], 20)
+ self.assertFalse(S._APDU_TIME_COLLECT)
+ self.assertEqual(S._APDU_TIMES, [])
+
+ def test_collect_reattaches_tracer_when_missing(self):
+ tp = types.SimpleNamespace(apdu_tracer=None)
+ scc = types.SimpleNamespace(_tp=tp)
+ S._server_ref = types.SimpleNamespace(scc=scc)
+ S._collect_apdu_times()
+ try:
+ self.assertIsInstance(tp.apdu_tracer, S._LoggingApduTracer)
+ finally:
+ S._end_apdu_time_collection()
+
+ def test_collect_keeps_existing_tracer(self):
+ tracer = S.StderrApduTracer()
+ tp = types.SimpleNamespace(apdu_tracer=tracer)
+ scc = types.SimpleNamespace(_tp=tp)
+ S._server_ref = types.SimpleNamespace(scc=scc)
+ S._collect_apdu_times()
+ try:
+ self.assertIs(tp.apdu_tracer, tracer)
+ finally:
+ S._end_apdu_time_collection()
+
+
+if __name__ == '__main__':
+ unittest.main()