Author: Richard Plangger <planri...@gmail.com> Branch: Changeset: r85850:1a36f95ed5d8 Date: 2016-07-25 11:03 +0200 http://bitbucket.org/pypy/pypy/changeset/1a36f95ed5d8/
Log: merge new-jit-log diff too long, truncating to 2000 out of 2221 lines diff --git a/pypy/config/pypyoption.py b/pypy/config/pypyoption.py --- a/pypy/config/pypyoption.py +++ b/pypy/config/pypyoption.py @@ -36,7 +36,7 @@ "cStringIO", "thread", "itertools", "pyexpat", "_ssl", "cpyext", "array", "binascii", "_multiprocessing", '_warnings', "_collections", "_multibytecodec", "micronumpy", "_continuation", "_cffi_backend", - "_csv", "cppyy", "_pypyjson", + "_csv", "cppyy", "_pypyjson", "_jitlog" ]) from rpython.jit.backend import detect_cpu diff --git a/pypy/module/_jitlog/__init__.py b/pypy/module/_jitlog/__init__.py new file mode 100644 --- /dev/null +++ b/pypy/module/_jitlog/__init__.py @@ -0,0 +1,13 @@ +from pypy.interpreter.mixedmodule import MixedModule +from rpython.rlib.rvmprof import VMProfPlatformUnsupported + +class Module(MixedModule): + """ JitLog the new logging facility """ + appleveldefs = { + } + + interpleveldefs = { + 'enable': 'interp_jitlog.enable', + 'disable': 'interp_jitlog.disable', + 'JitlogError': 'space.fromcache(interp_jitlog.Cache).w_JitlogError', + } diff --git a/pypy/module/_jitlog/interp_jitlog.py b/pypy/module/_jitlog/interp_jitlog.py new file mode 100644 --- /dev/null +++ b/pypy/module/_jitlog/interp_jitlog.py @@ -0,0 +1,28 @@ +from pypy.interpreter.error import OperationError +from pypy.interpreter.gateway import unwrap_spec +from pypy.interpreter.pyframe import PyFrame +from pypy.interpreter.pycode import PyCode +from pypy.interpreter.baseobjspace import W_Root +from rpython.rlib.rjitlog import rjitlog +from rpython.rlib import jit + +class Cache: + def __init__(self, space): + self.w_JitlogError = space.new_exception_class("_jitlog.JitlogError") + +def JitlogError(space, e): + w_JitlogError = space.fromcache(Cache).w_JitlogError + return OperationError(w_JitlogError, space.wrap(e.msg)) + +@unwrap_spec(fileno=int) +def enable(space, fileno): + """ Enable PyPy's logging facility. """ + try: + rjitlog.enable_jitlog(fileno) + except rjitlog.JitlogError, e: + raise JitlogError(space, e) + +@jit.dont_look_inside +def disable(space): + """ Disable PyPy's logging facility. """ + rjitlog.disable_jitlog() diff --git a/pypy/module/_jitlog/test/__init__.py b/pypy/module/_jitlog/test/__init__.py new file mode 100644 diff --git a/pypy/module/_jitlog/test/test__jitlog.py b/pypy/module/_jitlog/test/test__jitlog.py new file mode 100644 --- /dev/null +++ b/pypy/module/_jitlog/test/test__jitlog.py @@ -0,0 +1,29 @@ + +from rpython.tool.udir import udir +from pypy.tool.pytest.objspace import gettestobjspace +from rpython.rlib.rjitlog import rjitlog as jl + +class AppTestJitLog(object): + spaceconfig = {'usemodules': ['_jitlog', 'struct']} + + def setup_class(cls): + cls.w_tmpfilename = cls.space.wrap(str(udir.join('test__jitlog.1'))) + cls.w_mark_header = cls.space.wrap(jl.MARK_JITLOG_HEADER) + cls.w_version = cls.space.wrap(jl.JITLOG_VERSION_16BIT_LE) + + def test_enable(self): + import _jitlog, struct + tmpfile = open(self.tmpfilename, 'wb') + fileno = tmpfile.fileno() + _jitlog.enable(fileno) + _jitlog.disable() + # no need to clsoe tmpfile, it is done by jitlog + + with open(self.tmpfilename, 'rb') as fd: + assert fd.read(1) == self.mark_header + assert fd.read(2) == self.version + count, = struct.unpack('<h', fd.read(2)) + for i in range(count): + opnum = struct.unpack('<h', fd.read(2)) + strcount = struct.unpack('<i', fd.read(4)) + fd.read(strcount) diff --git a/pypy/module/_vmprof/interp_vmprof.py b/pypy/module/_vmprof/interp_vmprof.py --- a/pypy/module/_vmprof/interp_vmprof.py +++ b/pypy/module/_vmprof/interp_vmprof.py @@ -3,7 +3,7 @@ from pypy.interpreter.pyframe import PyFrame from pypy.interpreter.pycode import PyCode from pypy.interpreter.baseobjspace import W_Root -from rpython.rlib import rvmprof +from rpython.rlib import rvmprof, jit # ____________________________________________________________ diff --git a/pypy/module/pypyjit/interp_jit.py b/pypy/module/pypyjit/interp_jit.py --- a/pypy/module/pypyjit/interp_jit.py +++ b/pypy/module/pypyjit/interp_jit.py @@ -6,6 +6,7 @@ from rpython.rlib.rarithmetic import r_uint, intmask from rpython.rlib.jit import JitDriver, hint, we_are_jitted, dont_look_inside from rpython.rlib import jit, jit_hooks +from rpython.rlib.rjitlog import rjitlog as jl from rpython.rlib.jit import current_trace_length, unroll_parameters,\ JitHookInterface from rpython.rtyper.annlowlevel import cast_instance_to_gcref @@ -41,6 +42,19 @@ from rpython.rlib import rvmprof return rvmprof.get_unique_id(bytecode) +@jl.returns(jl.MP_FILENAME, jl.MP_LINENO, + jl.MP_SCOPE, jl.MP_INDEX, jl.MP_OPCODE) +def get_location(next_instr, is_being_profiled, bytecode): + from pypy.tool.stdlib_opcode import opcode_method_names + bcindex = ord(bytecode.co_code[next_instr]) + opname = "" + if 0 <= bcindex < len(opcode_method_names): + opname = opcode_method_names[bcindex] + name = bytecode.co_name + if not name: + name = "" + return (bytecode.co_filename, bytecode.co_firstlineno, + name, intmask(next_instr), opname) def should_unroll_one_iteration(next_instr, is_being_profiled, bytecode): return (bytecode.co_flags & CO_GENERATOR) != 0 @@ -51,6 +65,7 @@ virtualizables = ['frame'] pypyjitdriver = PyPyJitDriver(get_printable_location = get_printable_location, + get_location = get_location, get_unique_id = get_unique_id, should_unroll_one_iteration = should_unroll_one_iteration, diff --git a/pypy/module/pypyjit/test_pypy_c/test_00_model.py b/pypy/module/pypyjit/test_pypy_c/test_00_model.py --- a/pypy/module/pypyjit/test_pypy_c/test_00_model.py +++ b/pypy/module/pypyjit/test_pypy_c/test_00_model.py @@ -57,7 +57,10 @@ cmdline.append(str(self.filepath)) # env = os.environ.copy() + # TODO old logging system env['PYPYLOG'] = self.log_string + ':' + str(logfile) + jitlogfile = str(logfile) + '.jlog' + env['JITLOG'] = str(jitlogfile) pipe = subprocess.Popen(cmdline, env=env, stdout=subprocess.PIPE, @@ -84,6 +87,7 @@ log = Log(rawtraces) log.result = eval(stdout) log.logfile = str(logfile) + log.jitlogfile = jitlogfile # summaries = logparser.extract_category(rawlog, 'jit-summary') if len(summaries) > 0: diff --git a/pypy/module/pypyjit/test_pypy_c/test_jitlogparser.py b/pypy/module/pypyjit/test_pypy_c/test_jitlogparser.py --- a/pypy/module/pypyjit/test_pypy_c/test_jitlogparser.py +++ b/pypy/module/pypyjit/test_pypy_c/test_jitlogparser.py @@ -8,7 +8,6 @@ mangle_descr) from pypy.module.pypyjit.test_pypy_c.test_00_model import BaseTestPyPyC - class TestLogParser(BaseTestPyPyC): log_string = 'jit-log-opt,jit-backend' diff --git a/rpython/jit/backend/arm/assembler.py b/rpython/jit/backend/arm/assembler.py --- a/rpython/jit/backend/arm/assembler.py +++ b/rpython/jit/backend/arm/assembler.py @@ -14,7 +14,7 @@ CoreRegisterManager, check_imm_arg, VFPRegisterManager, operations as regalloc_operations) from rpython.jit.backend.llsupport import jitframe, rewrite -from rpython.jit.backend.llsupport.assembler import DEBUG_COUNTER, BaseAssembler +from rpython.jit.backend.llsupport.assembler import BaseAssembler from rpython.jit.backend.llsupport.regalloc import get_scale, valid_addressing_size from rpython.jit.backend.llsupport.asmmemmgr import MachineDataBlockWrapper from rpython.jit.backend.model import CompiledLoopToken @@ -633,9 +633,17 @@ 'loop.asm') ops_offset = self.mc.ops_offset - if logger is not None: - logger.log_loop(inputargs, operations, 0, "rewritten", - name=loopname, ops_offset=ops_offset) + + if logger: + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset=ops_offset) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_loop(inputargs, operations, 0, + "rewritten", name=loopname, + ops_offset=ops_offset) + self.teardown() debug_start("jit-backend-addr") @@ -735,9 +743,18 @@ frame_depth_no_fixed_size + JITFRAME_FIXED_SIZE) self.fixup_target_tokens(rawstart) self.update_frame_depth(frame_depth) + if logger: - logger.log_bridge(inputargs, operations, "rewritten", faildescr, - ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset) + # log that the already written bridge is stitched to a descr! + logger.log_patch_guard(descr_number, rawstart) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_bridge(inputargs, operations, "rewritten", + faildescr, ops_offset=ops_offset) + self.teardown() return AsmInfo(ops_offset, startpos + rawstart, codeendpos - startpos) diff --git a/rpython/jit/backend/llsupport/asmmemmgr.py b/rpython/jit/backend/llsupport/asmmemmgr.py --- a/rpython/jit/backend/llsupport/asmmemmgr.py +++ b/rpython/jit/backend/llsupport/asmmemmgr.py @@ -223,6 +223,7 @@ self.init_block_builder() else: self._become_a_plain_block_builder() + self.rawstart = 0 def init_block_builder(self): self._cursubblock = lltype.nullptr(self.SUBBLOCK) @@ -245,6 +246,9 @@ self._cursubblock.data[index] = char self._cursubindex = index + 1 + def absolute_addr(self): + return self.rawstart + def overwrite(self, index, char): assert 0 <= index < self.get_relative_pos() block = self._cursubblock @@ -280,6 +284,19 @@ targetindex -= self.SUBBLOCK_SIZE assert not block + def copy_core_dump(self, addr, offset=0, count=-1): + HEX = '0123456789ABCDEF' + dump = [] + src = rffi.cast(rffi.CCHARP, addr) + end = self.get_relative_pos() + if count != -1: + end = offset + count + for p in range(offset, end): + o = ord(src[p]) + dump.append(HEX[o >> 4]) + dump.append(HEX[o & 15]) + return ''.join(dump) + def _dump(self, addr, logname, backend=None): debug_start(logname) if have_debug_prints(): @@ -293,17 +310,11 @@ else: debug_print('SYS_EXECUTABLE', '??') # - HEX = '0123456789ABCDEF' - dump = [] - src = rffi.cast(rffi.CCHARP, addr) - for p in range(self.get_relative_pos()): - o = ord(src[p]) - dump.append(HEX[o >> 4]) - dump.append(HEX[o & 15]) + dump = self.copy_core_dump(addr) debug_print('CODE_DUMP', '@%x' % addr, '+0 ', # backwards compatibility - ''.join(dump)) + dump) # debug_stop(logname) @@ -315,6 +326,7 @@ allblocks.append(malloced) rawstart = malloced[0] rawstart = (rawstart + align - 1) & (-align) + self.rawstart = rawstart self.copy_to_raw_memory(rawstart) if self.gcroot_markers is not None: assert gcrootmap is not None diff --git a/rpython/jit/backend/llsupport/assembler.py b/rpython/jit/backend/llsupport/assembler.py --- a/rpython/jit/backend/llsupport/assembler.py +++ b/rpython/jit/backend/llsupport/assembler.py @@ -12,7 +12,7 @@ from rpython.rlib.objectmodel import specialize, compute_unique_id from rpython.rtyper.annlowlevel import cast_instance_to_gcref, llhelper from rpython.rtyper.lltypesystem import rffi, lltype - +from rpython.rlib.rjitlog import rjitlog as jl DEBUG_COUNTER = lltype.Struct('DEBUG_COUNTER', # 'b'ridge, 'l'abel or # 'e'ntry point @@ -73,7 +73,9 @@ self.memcpy_addr = 0 self.memset_addr = 0 self.rtyper = cpu.rtyper + # do not rely on this attribute if you test for jitlog self._debug = False + self.loop_run_counters = [] def stitch_bridge(self, faildescr, target): raise NotImplementedError @@ -129,11 +131,13 @@ self._build_stack_check_slowpath() self._build_release_gil(gc_ll_descr.gcrootmap) + # do not rely on the attribute _debug for jitlog if not self._debug: # if self._debug is already set it means that someone called # set_debug by hand before initializing the assembler. Leave it # as it is - self.set_debug(have_debug_prints_for('jit-backend-counts')) + should_debug = have_debug_prints_for('jit-backend-counts') + self.set_debug(should_debug) # when finishing, we only have one value at [0], the rest dies self.gcmap_for_finish = lltype.malloc(jitframe.GCMAP, 1, flavor='raw', @@ -337,16 +341,14 @@ # Here we join Path A and Path B again self._call_assembler_patch_jmp(jmp_location) + def get_loop_run_counters(self, index): + return self.loop_run_counters[index] + @specialize.argtype(1) def _inject_debugging_code(self, looptoken, operations, tp, number): - if self._debug: - s = 0 - for op in operations: - s += op.getopnum() - + if self._debug or jl.jitlog_enabled(): newoperations = [] - self._append_debugging_code(newoperations, tp, number, - None) + self._append_debugging_code(newoperations, tp, number, None) for op in operations: newoperations.append(op) if op.getopnum() == rop.LABEL: @@ -362,10 +364,6 @@ ResOperation(rop.INCREMENT_DEBUG_COUNTER, [c_adr])) def _register_counter(self, tp, number, token): - # YYY very minor leak -- we need the counters to stay alive - # forever, just because we want to report them at the end - # of the process - # XXX the numbers here are ALMOST unique, but not quite, use a counter # or something struct = lltype.malloc(DEBUG_COUNTER, flavor='raw', @@ -377,13 +375,18 @@ else: assert token struct.number = compute_unique_id(token) + # YYY very minor leak -- we need the counters to stay alive + # forever, just because we want to report them at the end + # of the process self.loop_run_counters.append(struct) return struct def finish_once(self): if self._debug: + # TODO remove the old logging system when jitlog is complete debug_start('jit-backend-counts') - for i in range(len(self.loop_run_counters)): + length = len(self.loop_run_counters) + for i in range(length): struct = self.loop_run_counters[i] if struct.type == 'l': prefix = 'TargetToken(%d)' % struct.number @@ -400,6 +403,23 @@ debug_print(prefix + ':' + str(struct.i)) debug_stop('jit-backend-counts') + self.flush_trace_counters() + + def flush_trace_counters(self): + # this is always called, the jitlog knows if it is enabled + length = len(self.loop_run_counters) + for i in range(length): + struct = self.loop_run_counters[i] + # only log if it has been executed + if struct.i > 0: + jl._log_jit_counter(struct) + # reset the counter, flush in a later point in time will + # add up the counters! + struct.i = 0 + # here would be the point to free some counters + # see YYY comment above! but first we should run this every once in a while + # not just when jitlog_disable is called + @staticmethod @rgc.no_collect def _reacquire_gil_asmgcc(css, old_rpy_fastgil): diff --git a/rpython/jit/backend/llsupport/llmodel.py b/rpython/jit/backend/llsupport/llmodel.py --- a/rpython/jit/backend/llsupport/llmodel.py +++ b/rpython/jit/backend/llsupport/llmodel.py @@ -113,7 +113,7 @@ unique_id=0, log=True, name='', logger=None): return self.assembler.assemble_loop(jd_id, unique_id, logger, name, inputargs, operations, - looptoken, log=log) + looptoken, log) def stitch_bridge(self, faildescr, target): self.assembler.stitch_bridge(faildescr, target) diff --git a/rpython/jit/backend/llsupport/test/ztranslation_test.py b/rpython/jit/backend/llsupport/test/ztranslation_test.py --- a/rpython/jit/backend/llsupport/test/ztranslation_test.py +++ b/rpython/jit/backend/llsupport/test/ztranslation_test.py @@ -12,6 +12,7 @@ from rpython.config.config import ConfigError from rpython.translator.tool.cbuild import ExternalCompilationInfo from rpython.rtyper.lltypesystem import lltype, rffi +from rpython.rlib.rjitlog import rjitlog as jl class TranslationTest(CCompiledMixin): @@ -48,9 +49,16 @@ lltype.Float, macro=True, releasegil=True, compilation_info=eci) + @jl.returns(jl.MP_FILENAME, + jl.MP_LINENO, + jl.MP_INDEX) + def get_location(): + return ("/home.py",0,0) + jitdriver = JitDriver(greens = [], reds = ['total', 'frame', 'j'], - virtualizables = ['frame']) + virtualizables = ['frame'], + get_location = get_location) def f(i, j): for param, _ in unroll_parameters: defl = PARAMETERS[param] @@ -233,6 +241,23 @@ assert res == 2 # one for loop and one for the prologue, no unrolling + def test_flush_trace_counts(self): + driver = JitDriver(greens = [], reds = ['i']) + + def f(): + i = 0 + while i < 100000: + driver.jit_merge_point(i=i) + i += 1 + + def main(): + jit_hooks.stats_set_debug(None, True) + f() + jl.stats_flush_trace_counts(None) + return 0 + + res = self.meta_interp(main, []) + assert res == 0 class TranslationRemoveTypePtrTest(CCompiledMixin): CPUClass = getcpuclass() diff --git a/rpython/jit/backend/ppc/ppc_assembler.py b/rpython/jit/backend/ppc/ppc_assembler.py --- a/rpython/jit/backend/ppc/ppc_assembler.py +++ b/rpython/jit/backend/ppc/ppc_assembler.py @@ -36,6 +36,7 @@ from rpython.rlib.jit import AsmInfo from rpython.rlib.objectmodel import compute_unique_id from rpython.rlib.rarithmetic import r_uint +from rpython.rlib.rjitlog import rjitlog as jl memcpy_fn = rffi.llexternal('memcpy', [llmemory.Address, llmemory.Address, rffi.SIZE_T], lltype.Void, @@ -794,9 +795,16 @@ looptoken._ppc_fullsize = full_size looptoken._ppc_ops_offset = ops_offset looptoken._ll_function_addr = rawstart + if logger: - logger.log_loop(inputargs, operations, 0, "rewritten", - name=loopname, ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset=ops_offset) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_loop(inputargs, operations, 0, + "rewritten", name=loopname, + ops_offset=ops_offset) self.fixup_target_tokens(rawstart) self.teardown() @@ -863,9 +871,18 @@ ops_offset = self.mc.ops_offset frame_depth = max(self.current_clt.frame_info.jfi_frame_depth, frame_depth_no_fixed_size + JITFRAME_FIXED_SIZE) + if logger: - logger.log_bridge(inputargs, operations, "rewritten", - ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset) + # log that the already written bridge is stitched to a descr! + logger.log_patch_guard(descr_number, rawstart) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_bridge(inputargs, operations, "rewritten", + faildescr, ops_offset=ops_offset) + self.fixup_target_tokens(rawstart) self.update_frame_depth(frame_depth) self.teardown() diff --git a/rpython/jit/backend/test/jitlog_test.py b/rpython/jit/backend/test/jitlog_test.py new file mode 100644 --- /dev/null +++ b/rpython/jit/backend/test/jitlog_test.py @@ -0,0 +1,80 @@ +import re +import os +from rpython.rlib import debug +from rpython.jit.tool.oparser import pure_parse +from rpython.jit.metainterp import logger +from rpython.jit.metainterp.typesystem import llhelper +from rpython.rlib.rjitlog import rjitlog as jl +from StringIO import StringIO +from rpython.jit.metainterp.optimizeopt.util import equaloplists +from rpython.jit.metainterp.history import AbstractDescr, JitCellToken, BasicFailDescr, BasicFinalDescr +from rpython.jit.backend.model import AbstractCPU +from rpython.rlib.jit import JitDriver +from rpython.rlib.objectmodel import always_inline +from rpython.jit.metainterp.test.support import LLJitMixin +from rpython.rlib.rjitlog import rjitlog +import tempfile + +class LoggerTest(LLJitMixin): + + def test_explicit_enable(self, tmpdir): + file = tmpdir.join('jitlog') + fileno = os.open(file.strpath, os.O_WRONLY | os.O_CREAT) + enable_jitlog = lambda: rjitlog.enable_jitlog(fileno) + f = self.run_sample_loop(enable_jitlog) + self.meta_interp(f, [10, 0]) + + assert os.path.exists(file.strpath) + with file.open('rb') as f: + # check the file header + assert f.read(3) == jl.MARK_JITLOG_HEADER + jl.JITLOG_VERSION_16BIT_LE + assert len(f.read()) > 0 + + def test_env(self, monkeypatch, tmpdir): + file = tmpdir.join('jitlog') + monkeypatch.setenv("JITLOG", file.strpath) + f = self.run_sample_loop(None) + self.meta_interp(f, [10,0]) + assert os.path.exists(file.strpath) + with file.open('rb') as fd: + # check the file header + assert fd.read(3) == jl.MARK_JITLOG_HEADER + jl.JITLOG_VERSION_16BIT_LE + assert len(fd.read()) > 0 + + def test_version(self, monkeypatch, tmpdir): + file = tmpdir.join('jitlog') + monkeypatch.setattr(jl, 'JITLOG_VERSION_16BIT_LE', '\xff\xfe') + monkeypatch.setenv("JITLOG", file.strpath) + f = self.run_sample_loop(None) + self.meta_interp(f, [10,0]) + assert os.path.exists(file.strpath) + with file.open('rb') as fd: + # check the file header + assert fd.read(3) == jl.MARK_JITLOG_HEADER + '\xff\xfe' + assert len(fd.read()) > 0 + + def test_version(self, monkeypatch, tmpdir): + file = tmpdir.join('jitlog') + monkeypatch.setattr(jl, 'JITLOG_VERSION_16BIT_LE', '\xff\xfe') + monkeypatch.setenv("JITLOG", file.strpath) + f = self.run_sample_loop(None) + self.meta_interp(f, [10,0]) + assert os.path.exists(file.strpath) + with file.open('rb') as fd: + # check the file header + assert fd.read(3) == jl.MARK_JITLOG_HEADER + '\xff\xfe' + assert len(fd.read()) > 0 + + def run_sample_loop(self, func, myjitdriver = None): + if not myjitdriver: + myjitdriver = JitDriver(greens = [], reds = 'auto') + def f(y, x): + res = 0 + if func: + func() + while y > 0: + myjitdriver.jit_merge_point() + res += x + y -= 1 + return res + return f diff --git a/rpython/jit/backend/x86/assembler.py b/rpython/jit/backend/x86/assembler.py --- a/rpython/jit/backend/x86/assembler.py +++ b/rpython/jit/backend/x86/assembler.py @@ -3,13 +3,13 @@ import py from rpython.jit.backend.llsupport import symbolic, jitframe, rewrite -from rpython.jit.backend.llsupport.assembler import (GuardToken, BaseAssembler, - DEBUG_COUNTER) +from rpython.jit.backend.llsupport.assembler import (GuardToken, BaseAssembler, debug_bridge) from rpython.jit.backend.llsupport.asmmemmgr import MachineDataBlockWrapper from rpython.jit.backend.llsupport.gcmap import allocate_gcmap from rpython.jit.metainterp.history import (Const, VOID, ConstInt) from rpython.jit.metainterp.history import AbstractFailDescr, INT, REF, FLOAT from rpython.jit.metainterp.compile import ResumeGuardDescr +from rpython.rlib.rjitlog import rjitlog as jl from rpython.rtyper.lltypesystem import lltype, rffi, rstr, llmemory from rpython.rtyper.lltypesystem.lloperation import llop from rpython.rtyper.annlowlevel import cast_instance_to_gcref @@ -490,8 +490,9 @@ clt.frame_info.clear() # for now if log: + number = looptoken.number operations = self._inject_debugging_code(looptoken, operations, - 'e', looptoken.number) + 'e', number) regalloc = RegAlloc(self, self.cpu.translate_support_code) # @@ -538,9 +539,16 @@ looptoken._x86_fullsize = full_size looptoken._x86_ops_offset = ops_offset looptoken._ll_function_addr = rawstart + functionpos + if logger: - logger.log_loop(inputargs, operations, 0, "rewritten", - name=loopname, ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset=ops_offset) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_loop(inputargs, operations, 0, + "rewritten", name=loopname, + ops_offset=ops_offset) self.fixup_target_tokens(rawstart) self.teardown() @@ -605,9 +613,18 @@ ops_offset = self.mc.ops_offset frame_depth = max(self.current_clt.frame_info.jfi_frame_depth, frame_depth_no_fixed_size + JITFRAME_FIXED_SIZE) + if logger: - logger.log_bridge(inputargs, operations, "rewritten", faildescr, - ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset) + # log that the already written bridge is stitched to a descr! + logger.log_patch_guard(descr_number, rawstart) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_bridge(inputargs, operations, "rewritten", + faildescr, ops_offset=ops_offset) + self.fixup_target_tokens(rawstart) self.update_frame_depth(frame_depth) self.teardown() diff --git a/rpython/jit/backend/x86/runner.py b/rpython/jit/backend/x86/runner.py --- a/rpython/jit/backend/x86/runner.py +++ b/rpython/jit/backend/x86/runner.py @@ -114,9 +114,10 @@ looptoken.compiled_loop_token.invalidate_positions = [] def get_all_loop_runs(self): + asm = self.assembler l = lltype.malloc(LOOP_RUN_CONTAINER, - len(self.assembler.loop_run_counters)) - for i, ll_s in enumerate(self.assembler.loop_run_counters): + len(asm.loop_run_counters)) + for i, ll_s in enumerate(asm.loop_run_counters): l[i].type = ll_s.type l[i].number = ll_s.number l[i].counter = ll_s.i diff --git a/rpython/jit/backend/x86/test/test_jitlog.py b/rpython/jit/backend/x86/test/test_jitlog.py new file mode 100644 --- /dev/null +++ b/rpython/jit/backend/x86/test/test_jitlog.py @@ -0,0 +1,8 @@ + +from rpython.jit.backend.x86.test.test_basic import Jit386Mixin +from rpython.jit.backend.test.jitlog_test import LoggerTest + +class TestJitlog(Jit386Mixin, LoggerTest): + # for the individual tests see + # ====> ../../../test/jitlog_test.py + pass diff --git a/rpython/jit/backend/x86/test/test_runner.py b/rpython/jit/backend/x86/test/test_runner.py --- a/rpython/jit/backend/x86/test/test_runner.py +++ b/rpython/jit/backend/x86/test/test_runner.py @@ -590,11 +590,11 @@ self.cpu.compile_loop(ops.inputargs, ops.operations, looptoken) self.cpu.execute_token(looptoken, 0) # check debugging info - struct = self.cpu.assembler.loop_run_counters[0] + struct = self.cpu.assembler.get_loop_run_counters(0) assert struct.i == 1 - struct = self.cpu.assembler.loop_run_counters[1] + struct = self.cpu.assembler.get_loop_run_counters(1) assert struct.i == 1 - struct = self.cpu.assembler.loop_run_counters[2] + struct = self.cpu.assembler.get_loop_run_counters(2) assert struct.i == 9 self.cpu.finish_once() finally: diff --git a/rpython/jit/backend/zarch/assembler.py b/rpython/jit/backend/zarch/assembler.py --- a/rpython/jit/backend/zarch/assembler.py +++ b/rpython/jit/backend/zarch/assembler.py @@ -32,6 +32,7 @@ from rpython.rtyper.lltypesystem import lltype, rffi, llmemory from rpython.rtyper.annlowlevel import llhelper, cast_instance_to_gcref from rpython.rlib.jit import AsmInfo +from rpython.rlib.rjitlog import rjitlog as jl class JitFrameTooDeep(Exception): pass @@ -669,9 +670,16 @@ looptoken._zarch_rawstart = rawstart looptoken._zarch_fullsize = full_size looptoken._zarch_ops_offset = ops_offset + if logger: - logger.log_loop(inputargs, operations, 0, "rewritten", - name=loopname, ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset=ops_offset) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_loop(inputargs, operations, 0, + "rewritten", name=loopname, + ops_offset=ops_offset) self.fixup_target_tokens(rawstart) self.teardown() @@ -736,9 +744,18 @@ ops_offset = self.mc.ops_offset frame_depth = max(self.current_clt.frame_info.jfi_frame_depth, frame_depth_no_fixed_size + JITFRAME_FIXED_SIZE) + if logger: - logger.log_bridge(inputargs, operations, "rewritten", - ops_offset=ops_offset) + log = logger.log_trace(jl.MARK_TRACE_ASM, None, self.mc) + log.write(inputargs, operations, ops_offset) + # log that the already written bridge is stitched to a descr! + logger.log_patch_guard(descr_number, rawstart) + + # legacy + if logger.logger_ops: + logger.logger_ops.log_bridge(inputargs, operations, "rewritten", + faildescr, ops_offset=ops_offset) + self.fixup_target_tokens(rawstart) self.update_frame_depth(frame_depth) self.teardown() diff --git a/rpython/jit/backend/zarch/test/test_jitlog.py b/rpython/jit/backend/zarch/test/test_jitlog.py new file mode 100644 --- /dev/null +++ b/rpython/jit/backend/zarch/test/test_jitlog.py @@ -0,0 +1,8 @@ + +from rpython.jit.backend.zarch.test.support import JitZARCHMixin +from rpython.jit.backend.test.jitlog_test import LoggerTest + +class TestJitlog(JitZARCHMixin, LoggerTest): + # for the individual tests see + # ====> ../../../test/jitlog_test.py + pass diff --git a/rpython/jit/metainterp/compile.py b/rpython/jit/metainterp/compile.py --- a/rpython/jit/metainterp/compile.py +++ b/rpython/jit/metainterp/compile.py @@ -6,6 +6,7 @@ from rpython.rlib.rarithmetic import r_uint, intmask from rpython.rlib import rstack from rpython.rlib.jit import JitDebugInfo, Counters, dont_look_inside +from rpython.rlib.rjitlog import rjitlog as jl from rpython.conftest import option from rpython.jit.metainterp.resoperation import ResOperation, rop,\ @@ -217,6 +218,7 @@ loop_info, ops = optimize_trace(metainterp_sd, jitdriver_sd, data, metainterp.box_names_memo) except InvalidLoop: + metainterp_sd.jitlog.trace_aborted() trace.cut_at(cut_at) return None loop = create_empty_loop(metainterp) @@ -250,7 +252,9 @@ history = metainterp.history trace = history.trace warmstate = jitdriver_sd.warmstate - + # + metainterp_sd.jitlog.start_new_trace(metainterp_sd, None, False) + # enable_opts = jitdriver_sd.warmstate.enable_opts if try_disabling_unroll: if 'unroll' not in enable_opts: @@ -275,6 +279,7 @@ preamble_data, metainterp.box_names_memo) except InvalidLoop: + metainterp_sd.jitlog.trace_aborted() history.cut(cut_at) return None @@ -291,6 +296,7 @@ loop_data, metainterp.box_names_memo) except InvalidLoop: + metainterp_sd.jitlog.trace_aborted() history.cut(cut_at) return None @@ -340,7 +346,9 @@ metainterp_sd = metainterp.staticdata jitdriver_sd = metainterp.jitdriver_sd history = metainterp.history - + # + metainterp_sd.jitlog.start_new_trace(metainterp_sd, resumekey, False) + # loop_jitcell_token = metainterp.get_procedure_token(greenkey) assert loop_jitcell_token @@ -368,6 +376,7 @@ loop_data, metainterp.box_names_memo) except InvalidLoop: + metainterp_sd.jitlog.trace_aborted() history.cut(cut) return None @@ -476,22 +485,28 @@ def do_compile_loop(jd_id, unique_id, metainterp_sd, inputargs, operations, looptoken, log=True, name='', memo=None): + # legacy metainterp_sd.logger_ops.log_loop(inputargs, operations, -2, 'compiling', None, name, memo) + _log = metainterp_sd.jitlog.log_trace(jl.MARK_TRACE_OPT, metainterp_sd, None) + _log.write(inputargs, operations) return metainterp_sd.cpu.compile_loop(inputargs, operations, looptoken, jd_id=jd_id, unique_id=unique_id, log=log, name=name, - logger=metainterp_sd.logger_ops) + logger=metainterp_sd.jitlog) def do_compile_bridge(metainterp_sd, faildescr, inputargs, operations, original_loop_token, log=True, memo=None): + # legacy metainterp_sd.logger_ops.log_bridge(inputargs, operations, "compiling", memo=memo) + _log = metainterp_sd.jitlog.log_trace(jl.MARK_TRACE_OPT, metainterp_sd, None) + _log.write(inputargs, operations) assert isinstance(faildescr, AbstractFailDescr) return metainterp_sd.cpu.compile_bridge(faildescr, inputargs, operations, original_loop_token, log=log, - logger=metainterp_sd.logger_ops) + logger=metainterp_sd.jitlog) def forget_optimization_info(lst, reset_values=False): for item in lst: @@ -511,9 +526,7 @@ patch_new_loop_to_load_virtualizable_fields(loop, jitdriver_sd, vable) original_jitcell_token = loop.original_jitcell_token - globaldata = metainterp_sd.globaldata - original_jitcell_token.number = n = globaldata.loopnumbering - globaldata.loopnumbering += 1 + original_jitcell_token.number = n = metainterp_sd.jitlog.trace_id if not we_are_translated(): show_procedures(metainterp_sd, loop) @@ -531,6 +544,7 @@ operations = get_deep_immutable_oplist(loop.operations) metainterp_sd.profiler.start_backend() debug_start("jit-backend") + log = have_debug_prints() or jl.jitlog_enabled() try: loopname = jitdriver_sd.warmstate.get_location_str(greenkey) unique_id = jitdriver_sd.warmstate.get_unique_id(greenkey) @@ -538,7 +552,7 @@ loop.inputargs, operations, original_jitcell_token, name=loopname, - log=have_debug_prints(), + log=log, memo=memo) finally: debug_stop("jit-backend") @@ -582,10 +596,11 @@ operations = get_deep_immutable_oplist(operations) metainterp_sd.profiler.start_backend() debug_start("jit-backend") + log = have_debug_prints() or jl.jitlog_enabled() try: asminfo = do_compile_bridge(metainterp_sd, faildescr, inputargs, operations, - original_loop_token, have_debug_prints(), + original_loop_token, log, memo) finally: debug_stop("jit-backend") @@ -1020,7 +1035,7 @@ def compile_trace(metainterp, resumekey, runtime_boxes): """Try to compile a new bridge leading from the beginning of the history - to some existging place. + to some existing place. """ from rpython.jit.metainterp.optimizeopt import optimize_trace @@ -1033,6 +1048,9 @@ metainterp_sd = metainterp.staticdata jitdriver_sd = metainterp.jitdriver_sd + # + metainterp_sd.jitlog.start_new_trace(metainterp_sd, resumekey, False) + # if isinstance(resumekey, ResumeAtPositionDescr): inline_short_preamble = False else: @@ -1057,6 +1075,7 @@ info, newops = optimize_trace(metainterp_sd, jitdriver_sd, data, metainterp.box_names_memo) except InvalidLoop: + metainterp_sd.jitlog.trace_aborted() #pdb.post_mortem(sys.exc_info()[2]) debug_print("compile_new_bridge: got an InvalidLoop") # XXX I am fairly convinced that optimize_bridge cannot actually raise diff --git a/rpython/jit/metainterp/optimizeopt/__init__.py b/rpython/jit/metainterp/optimizeopt/__init__.py --- a/rpython/jit/metainterp/optimizeopt/__init__.py +++ b/rpython/jit/metainterp/optimizeopt/__init__.py @@ -7,6 +7,7 @@ from rpython.jit.metainterp.optimizeopt.simplify import OptSimplify from rpython.jit.metainterp.optimizeopt.pure import OptPure from rpython.jit.metainterp.optimizeopt.earlyforce import OptEarlyForce +from rpython.rlib.rjitlog import rjitlog as jl from rpython.rlib.jit import PARAMETERS, ENABLE_ALL_OPTS from rpython.rlib.unroll import unrolling_iterable from rpython.rlib.debug import debug_start, debug_stop, debug_print @@ -53,6 +54,9 @@ """ debug_start("jit-optimize") try: + # mark that a new trace has been started + log = metainterp_sd.jitlog.log_trace(jl.MARK_TRACE, metainterp_sd, None) + log.write_trace(compile_data.trace) if compile_data.log_noopt: metainterp_sd.logger_noopt.log_loop_from_trace(compile_data.trace, memo=memo) if memo is None: diff --git a/rpython/jit/metainterp/optimizeopt/dependency.py b/rpython/jit/metainterp/optimizeopt/dependency.py --- a/rpython/jit/metainterp/optimizeopt/dependency.py +++ b/rpython/jit/metainterp/optimizeopt/dependency.py @@ -22,6 +22,8 @@ , (rop.UNICODESETITEM, 0, -1) ] +UNROLLED_MODIFY_COMPLEX_OBJ = unrolling_iterable(MODIFY_COMPLEX_OBJ) + LOAD_COMPLEX_OBJ = [ (rop.GETARRAYITEM_GC_I, 0, 1) , (rop.GETARRAYITEM_GC_F, 0, 1) , (rop.GETARRAYITEM_GC_R, 0, 1) @@ -40,6 +42,8 @@ , (rop.GETFIELD_RAW_R, 0, -1) ] +UNROLLED_LOAD_COMPLEX_OBJ = unrolling_iterable(LOAD_COMPLEX_OBJ) + class Path(object): def __init__(self,path): self.path = path @@ -202,7 +206,7 @@ args = [] op = self.op if self.modifies_complex_object(): - for opnum, i, j in unrolling_iterable(MODIFY_COMPLEX_OBJ): + for opnum, i, j in UNROLLED_MODIFY_COMPLEX_OBJ: #unrolling_iterable(MODIFY_COMPLEX_OBJ): if op.getopnum() == opnum: op_args = op.getarglist() if j == -1: @@ -723,7 +727,7 @@ if node.loads_from_complex_object(): # If this complex object load operation loads an index that has been # modified, the last modification should be used to put a def-use edge. - for opnum, i, j in unrolling_iterable(LOAD_COMPLEX_OBJ): + for opnum, i, j in UNROLLED_LOAD_COMPLEX_OBJ: if opnum == op.getopnum(): cobj = op.getarg(i) if j != -1: diff --git a/rpython/jit/metainterp/optimizeopt/test/test_util.py b/rpython/jit/metainterp/optimizeopt/test/test_util.py --- a/rpython/jit/metainterp/optimizeopt/test/test_util.py +++ b/rpython/jit/metainterp/optimizeopt/test/test_util.py @@ -21,6 +21,7 @@ from rpython.jit.metainterp.resoperation import (rop, ResOperation, InputArgRef, AbstractValue, OpHelpers) from rpython.jit.metainterp.optimizeopt.util import args_dict +from rpython.rlib.rjitlog import rjitlog as jl def test_sort_descrs(): @@ -484,6 +485,7 @@ self.options = Fake() self.globaldata = Fake() self.config = get_combined_translation_config(translating=True) + self.jitlog = jl.JitLogger() class logger_noopt: @classmethod diff --git a/rpython/jit/metainterp/pyjitpl.py b/rpython/jit/metainterp/pyjitpl.py --- a/rpython/jit/metainterp/pyjitpl.py +++ b/rpython/jit/metainterp/pyjitpl.py @@ -13,6 +13,7 @@ from rpython.jit.metainterp.logger import Logger from rpython.jit.metainterp.optimizeopt.util import args_dict from rpython.jit.metainterp.resoperation import rop, OpHelpers, GuardResOp +from rpython.rlib.rjitlog import rjitlog as jl from rpython.rlib import nonconst, rstack from rpython.rlib.debug import debug_start, debug_stop, debug_print from rpython.rlib.debug import have_debug_prints, make_sure_not_resized @@ -1760,8 +1761,12 @@ self.cpu = cpu self.stats = self.cpu.stats self.options = options + self.jitlog = jl.JitLogger(self.cpu) self.logger_noopt = Logger(self) self.logger_ops = Logger(self, guard_number=True) + # legacy loggers + self.jitlog.logger_noopt = self.logger_noopt + self.jitlog.logger_ops = self.logger_ops self.profiler = ProfilerClass() self.profiler.cpu = cpu @@ -1849,6 +1854,7 @@ def _setup_once(self): """Runtime setup needed by the various components of the JIT.""" if not self.globaldata.initialized: + self.jitlog.setup_once() debug_print(self.jit_starting_line) self.cpu.setup_once() if not self.profiler.initialized: @@ -1925,7 +1931,6 @@ self.initialized = False self.indirectcall_dict = None self.addr2name = None - self.loopnumbering = 0 # ____________________________________________________________ diff --git a/rpython/jit/metainterp/test/test_compile.py b/rpython/jit/metainterp/test/test_compile.py --- a/rpython/jit/metainterp/test/test_compile.py +++ b/rpython/jit/metainterp/test/test_compile.py @@ -4,6 +4,7 @@ from rpython.jit.metainterp.compile import compile_loop from rpython.jit.metainterp.compile import compile_tmp_callback from rpython.jit.metainterp import jitexc +from rpython.rlib.rjitlog import rjitlog as jl from rpython.jit.metainterp import jitprof, typesystem, compile from rpython.jit.metainterp.optimizeopt.test.test_util import LLtypeMixin from rpython.jit.tool.oparser import parse, convert_loop_to_trace @@ -51,13 +52,14 @@ return 'location' class FakeGlobalData(object): - loopnumbering = 0 + pass class FakeMetaInterpStaticData(object): all_descrs = [] logger_noopt = FakeLogger() logger_ops = FakeLogger() config = get_combined_translation_config(translating=True) + jitlog = jl.JitLogger() stats = Stats(None) profiler = jitprof.EmptyProfiler() @@ -78,8 +80,8 @@ cpu = FakeCPU() staticdata = FakeMetaInterpStaticData() staticdata.cpu = cpu - staticdata.globaldata = FakeGlobalData() - staticdata.globaldata.loopnumbering = 1 + staticdata.jitlog = jl.JitLogger(cpu) + staticdata.jitlog.trace_id = 1 # loop = parse(''' [p1] @@ -106,8 +108,7 @@ jitcell_token = target_token.targeting_jitcell_token assert jitcell_token == target_token.original_jitcell_token assert jitcell_token.target_tokens == [target_token] - assert jitcell_token.number == 1 - assert staticdata.globaldata.loopnumbering == 2 + assert jitcell_token.number == 2 # assert len(cpu.seen) == 1 assert cpu.seen[0][2] == jitcell_token diff --git a/rpython/jit/metainterp/warmspot.py b/rpython/jit/metainterp/warmspot.py --- a/rpython/jit/metainterp/warmspot.py +++ b/rpython/jit/metainterp/warmspot.py @@ -6,6 +6,7 @@ cast_base_ptr_to_instance, hlstr, cast_instance_to_gcref) from rpython.rtyper.llannotation import lltype_to_annotation from rpython.annotator import model as annmodel +from rpython.annotator.dictdef import DictDef from rpython.rtyper.llinterp import LLException from rpython.rtyper.test.test_llinterp import get_interpreter, clear_tcache from rpython.flowspace.model import SpaceOperation, Variable, Constant @@ -119,6 +120,7 @@ return interp, graph res = interp.eval_graph(graph, args) if not kwds.get('translate_support_code', False): + warmrunnerdesc.metainterp_sd.jitlog.finish() warmrunnerdesc.metainterp_sd.profiler.finish() warmrunnerdesc.metainterp_sd.cpu.finish_once() print '~~~ return value:', repr(res) @@ -563,12 +565,12 @@ jd._EnterJitAssembler = EnterJitAssembler def make_driverhook_graphs(self): - s_Str = annmodel.SomeString() # annhelper = MixLevelHelperAnnotator(self.translator.rtyper) for jd in self.jitdrivers_sd: jd._get_printable_location_ptr = self._make_hook_graph(jd, - annhelper, jd.jitdriver.get_printable_location, s_Str) + annhelper, jd.jitdriver.get_printable_location, + annmodel.SomeString()) jd._get_unique_id_ptr = self._make_hook_graph(jd, annhelper, jd.jitdriver.get_unique_id, annmodel.SomeInteger()) jd._confirm_enter_jit_ptr = self._make_hook_graph(jd, @@ -579,6 +581,34 @@ jd._should_unroll_one_iteration_ptr = self._make_hook_graph(jd, annhelper, jd.jitdriver.should_unroll_one_iteration, annmodel.s_Bool) + # + items = [] + types = () + pos = () + if jd.jitdriver.get_location: + assert hasattr(jd.jitdriver.get_location, '_loc_types'), """ + You must decorate your get_location function: + + from rpython.rlib.rjitlog import rjitlog as jl + @jl.returns(jl.MP_FILENAME, jl.MP_XXX, ...) + def get_loc(your, green, keys): + name = "x.txt" # extract it from your green keys + return (name, ...) + """ + types = jd.jitdriver.get_location._loc_types + del jd.jitdriver.get_location._loc_types + # + for _,type in types: + if type == 's': + items.append(annmodel.SomeString()) + elif type == 'i': + items.append(annmodel.SomeInteger()) + else: + raise NotImplementedError + s_Tuple = annmodel.SomeTuple(items) + jd._get_location_ptr = self._make_hook_graph(jd, + annhelper, jd.jitdriver.get_location, s_Tuple) + jd._get_loc_types = types annhelper.finish() def _make_hook_graph(self, jitdriver_sd, annhelper, func, diff --git a/rpython/jit/metainterp/warmstate.py b/rpython/jit/metainterp/warmstate.py --- a/rpython/jit/metainterp/warmstate.py +++ b/rpython/jit/metainterp/warmstate.py @@ -6,6 +6,7 @@ from rpython.rlib.debug import debug_start, debug_stop, debug_print from rpython.rlib.debug import have_debug_prints_for from rpython.rlib.jit import PARAMETERS +from rpython.rlib.rjitlog import rjitlog as jl from rpython.rlib.nonconst import NonConstant from rpython.rlib.objectmodel import specialize, we_are_translated, r_dict from rpython.rlib.rarithmetic import intmask, r_uint @@ -703,8 +704,35 @@ drivername = jitdriver.name else: drivername = '<unknown jitdriver>' - get_location_ptr = self.jitdriver_sd._get_printable_location_ptr - if get_location_ptr is None: + # get_location returns + get_location_ptr = getattr(self.jitdriver_sd, '_get_location_ptr', None) + if get_location_ptr is not None: + types = self.jitdriver_sd._get_loc_types + unwrap_greenkey = self.make_unwrap_greenkey() + unrolled_types = unrolling_iterable(enumerate(types)) + def get_location(greenkey): + greenargs = unwrap_greenkey(greenkey) + fn = support.maybe_on_top_of_llinterp(rtyper, get_location_ptr) + value_tuple = fn(*greenargs) + values = [] + for i, (sem_type,gen_type) in unrolled_types: + if gen_type == "s": + value = getattr(value_tuple, 'item' + str(i)) + values.append(jl.wrap(sem_type,gen_type,hlstr(value))) + elif gen_type == "i": + value = getattr(value_tuple, 'item' + str(i)) + values.append(jl.wrap(sem_type,gen_type,intmask(value))) + else: + raise NotImplementedError + return values + self.get_location_types = list(types) + self.get_location = get_location + else: + self.get_location_types = None + self.get_location = None + # + printable_loc_ptr = self.jitdriver_sd._get_printable_location_ptr + if printable_loc_ptr is None: missing = '(%s: no get_printable_location)' % drivername def get_location_str(greenkey): return missing @@ -720,7 +748,7 @@ if not have_debug_prints_for("jit-"): return missing greenargs = unwrap_greenkey(greenkey) - fn = support.maybe_on_top_of_llinterp(rtyper, get_location_ptr) + fn = support.maybe_on_top_of_llinterp(rtyper, printable_loc_ptr) llres = fn(*greenargs) if not we_are_translated() and isinstance(llres, str): return llres diff --git a/rpython/rlib/jit.py b/rpython/rlib/jit.py --- a/rpython/rlib/jit.py +++ b/rpython/rlib/jit.py @@ -604,8 +604,27 @@ get_printable_location=None, confirm_enter_jit=None, can_never_inline=None, should_unroll_one_iteration=None, name='jitdriver', check_untranslated=True, vectorize=False, - get_unique_id=None, is_recursive=False): - "NOT_RPYTHON" + get_unique_id=None, is_recursive=False, get_location=None): + """ NOT_RPYTHON + get_location: + The return value is designed to provide enough information to express the + state of an interpreter when invoking jit_merge_point. + For a bytecode interperter such as PyPy this includes, filename, line number, + function name, and more information. However, it should also be able to express + the same state for an interpreter that evaluates an AST. + return paremter: + 0 -> filename. An absolute path specifying the file the interpreter invoked. + If the input source is no file it should start with the + prefix: "string://<name>" + 1 -> line number. The line number in filename. This should at least point to + the enclosing name. It can however point to the specific + source line of the instruction executed by the interpreter. + 2 -> enclosing name. E.g. the function name. + 3 -> index. 64 bit number indicating the execution progress. It can either be + an offset to byte code, or an index to the node in an AST + 4 -> operation name. a name further describing the current program counter. + this can be either a byte code name or the name of an AST node + """ if greens is not None: self.greens = greens self.name = name @@ -639,6 +658,7 @@ assert get_jitcell_at is None, "get_jitcell_at no longer used" assert set_jitcell_at is None, "set_jitcell_at no longer used" self.get_printable_location = get_printable_location + self.get_location = get_location if get_unique_id is None: get_unique_id = lambda *args: 0 self.get_unique_id = get_unique_id @@ -879,6 +899,7 @@ driver = self.instance.im_self h = self.annotate_hook h(driver.get_printable_location, driver.greens, **kwds_s) + h(driver.get_location, driver.greens, **kwds_s) def annotate_hook(self, func, variables, args_s=[], **kwds_s): if func is None: diff --git a/rpython/rlib/rjitlog/__init__.py b/rpython/rlib/rjitlog/__init__.py new file mode 100644 diff --git a/rpython/rlib/rjitlog/rjitlog.py b/rpython/rlib/rjitlog/rjitlog.py new file mode 100644 --- /dev/null +++ b/rpython/rlib/rjitlog/rjitlog.py @@ -0,0 +1,606 @@ +import py +import sys +import sys +import weakref +import struct +import os +from rpython.rlib import jit +from rpython.tool.udir import udir +from rpython.tool.version import rpythonroot +from rpython.rtyper.lltypesystem import lltype, rffi +from rpython.translator.tool.cbuild import ExternalCompilationInfo +from rpython.jit.metainterp import resoperation as resoperations +from rpython.jit.metainterp.resoperation import rop +from rpython.jit.metainterp.history import ConstInt, ConstFloat +from rpython.rlib.objectmodel import we_are_translated +from rpython.rtyper.lltypesystem import lltype, llmemory, rffi +from rpython.rlib.objectmodel import compute_unique_id, always_inline +from rpython.rlib.objectmodel import we_are_translated, specialize +from rpython.rlib.unroll import unrolling_iterable +from rpython.rlib.jit_hooks import register_helper +from rpython.annotator import model as annmodel + + +ROOT = py.path.local(rpythonroot).join('rpython', 'rlib', 'rjitlog') +SRC = ROOT.join('src') + +_libs = [] +if sys.platform.startswith('linux'): + _libs = ['dl'] +eci_kwds = dict( + include_dirs = [SRC], + includes = ['rjitlog.h'], + libraries = _libs, + separate_module_files = [SRC.join('rjitlog.c')], + post_include_bits=['#define RPYTHON_JITLOG\n'], + ) +eci = ExternalCompilationInfo(**eci_kwds) + +# jit log functions +jitlog_init = rffi.llexternal("jitlog_init", [rffi.INT], + rffi.CCHARP, compilation_info=eci) +jitlog_try_init_using_env = rffi.llexternal("jitlog_try_init_using_env", + [], lltype.Void, compilation_info=eci) +jitlog_write_marked = rffi.llexternal("jitlog_write_marked", + [rffi.CCHARP, rffi.INT], + lltype.Void, compilation_info=eci, + releasegil=False) +jitlog_enabled = rffi.llexternal("jitlog_enabled", [], rffi.INT, + compilation_info=eci, + releasegil=False) +jitlog_teardown = rffi.llexternal("jitlog_teardown", [], lltype.Void, + compilation_info=eci) + +class JitlogError(Exception): + def __init__(self, msg): + self.msg = msg + def __str__(self): + return self.msg + +@register_helper(None) +def stats_flush_trace_counts(warmrunnerdesc): + if not we_are_translated(): + return # first param is None untranslated + warmrunnerdesc.metainterp_sd.cpu.assembler.flush_trace_counters() + +@jit.dont_look_inside +def enable_jitlog(fileno): + # initialize the jit log + p_error = jitlog_init(fileno) + if p_error: + raise JitlogError(rffi.charp2str(p_error)) + blob = assemble_header() + jitlog_write_marked(MARK_JITLOG_HEADER + blob, len(blob) + 1) + +def disable_jitlog(): + stats_flush_trace_counts(None) + jitlog_teardown() + + +def commonprefix(a,b): + "Given a list of pathnames, returns the longest common leading component" + assert a is not None + assert b is not None + la = len(a) + lb = len(b) + c = min(la,lb) + if c == 0: + return "" + for i in range(c): + if a[i] != b[i]: + return a[:i] # partly matching + return a # full match + +@always_inline +def encode_str(string): + return encode_le_32bit(len(string)) + string + +@always_inline +def encode_le_16bit(val): + return chr((val >> 0) & 0xff) + chr((val >> 8) & 0xff) + +@always_inline +def encode_le_32bit(val): + return ''.join([chr((val >> 0) & 0xff), + chr((val >> 8) & 0xff), + chr((val >> 16) & 0xff), + chr((val >> 24) & 0xff)]) + +@always_inline +def encode_le_64bit(val): + return ''.join([chr((val >> 0) & 0xff), + chr((val >> 8) & 0xff), + chr((val >> 16) & 0xff), + chr((val >> 24) & 0xff), + chr((val >> 32) & 0xff), + chr((val >> 40) & 0xff), + chr((val >> 48) & 0xff), + chr((val >> 56)& 0xff)]) + +@always_inline +def encode_le_addr(val): + if IS_32_BIT: + return encode_le_32bit(val) + else: + return encode_le_64bit(val) + +def encode_type(type, value): + if type == "s": + return encode_str(value) + elif type == "q": + return encode_le_64bit(value) + elif type == "i": + return encode_le_32bit(value) + elif type == "h": + return encode_le_32bit(value) + else: + raise NotImplementedError + +# more variable parameters +MP_STR = (0x0, "s") +MP_INT = (0x0, "i") + +# concrete parameters +MP_FILENAME = (0x1, "s") +MP_LINENO = (0x2, "i") +MP_INDEX = (0x4, "i") +MP_SCOPE = (0x8, "s") +MP_OPCODE = (0x10, "s") + +class WrappedValue(object): + def encode(self, log, i, compressor): + raise NotImplementedError + +class StringValue(WrappedValue): + def __init__(self, sem_type, gen_type, value): + self.value = value + + def encode(self, log, i, compressor): + str_value = self.value + last_prefix = compressor.get_last_written(i) + cp = compressor.compress(i, str_value) + if cp is None: + return b'\xff' + encode_str(str_value) + + else: + cp_len = len(cp) + if cp == last_prefix: + # we have the same prefix + pass + else: + compressor.write(log, i, cp) + if len(str_value) == len(cp): + return b'\xef' + return b'\x00' + encode_str(str_value[len(cp):]) + +class IntValue(WrappedValue): + def __init__(self, sem_type, gen_type, value): + self.value = value + + def encode(self, log, i, prefixes): + return b'\x00' + encode_le_64bit(self.value) + +# note that a ... +# "semantic_type" is an integer denoting which meaning does a type at a merge point have +# there are very common ones that are predefined. E.g. MP_FILENAME +# "generic_type" is one of the primitive types supported (string,int) + +@specialize.argtype(2) +def wrap(sem_type, gen_type, value): + if isinstance(value, int): + return IntValue(sem_type, gen_type, value) + elif isinstance(value, str): + return StringValue(sem_type, gen_type, value) + raise NotImplementedError + +def returns(*args): + """ Decorate your get_location function to specify the types. + Use MP_* constant as parameters. An example impl for get_location + would return the following: + + @returns(MP_FILENAME, MP_LINENO) + def get_location(...): + return ("a.py", 0) + """ + def decor(method): + method._loc_types = args + return method + return decor + +JITLOG_VERSION = 1 +JITLOG_VERSION_16BIT_LE = struct.pack("<H", JITLOG_VERSION) + +marks = [ + ('INPUT_ARGS',), + ('RESOP_META',), + ('RESOP',), + ('RESOP_DESCR',), + ('ASM_ADDR',), + ('ASM',), + + # which type of trace is logged after this + # the trace as it is recorded by the tracer + ('TRACE',), + # the trace that has passed the optimizer + ('TRACE_OPT',), + # the trace assembled to machine code (after rewritten) + ('TRACE_ASM',), + + # the machine code was patched (e.g. guard) + ('STITCH_BRIDGE',), + + ('START_TRACE',), + + ('JITLOG_COUNTER',), + ('INIT_MERGE_POINT',), + + ('JITLOG_HEADER',), + ('MERGE_POINT',), + ('COMMON_PREFIX',), + ('ABORT_TRACE',), + ('SOURCE_CODE',), +] + +start = 0x11 +for mark, in marks: + globals()['MARK_' + mark] = chr(start) + start += 1 + +if __name__ == "__main__": + print("# generated constants from rpython/rlib/jitlog.py") + print 'MARK_JITLOG_START = struct.pack("b", "%s")' % hex(0x10) + for mark, in marks: + nmr = globals()['MARK_' + mark] + h = hex(ord(nmr)) + print '%s = struct.pack("b", "%s")' % ('MARK_' + mark, h) + print 'MARK_JITLOG_END = struct.pack("b", "%s")' % hex(start) + for key,value in locals().items(): + if key.startswith("MP_"): + print '%s = (%s,"%s")' % (key, hex(value[0]), value[1]) + print 'SEM_TYPE_NAMES = {' + for key,value in locals().items(): + if key.startswith("MP_") and value[0] != 0: + print ' %s: "%s",' % (hex(value[0]), key[3:].lower()) + print '}' + +MP_STR = (0x0, "s") +MP_INT = (0x0, "i") + +# concrete parameters +MP_FILENAME = (0x1, "s") +MP_LINENO = (0x2, "i") +MP_INDEX = (0x4, "i") +MP_SCOPE = (0x8, "s") +MP_OPCODE = (0x10, "s") + +del marks +del start + +IS_32_BIT = sys.maxint == 2**31-1 + +def assemble_header(): + version = JITLOG_VERSION_16BIT_LE + count = len(resoperations.opname) + content = [version, MARK_RESOP_META, + encode_le_16bit(count)] + for opnum, opname in resoperations.opname.items(): + content.append(encode_le_16bit(opnum)) + content.append(encode_str(opname.lower())) + return ''.join(content) + +def _log_jit_counter(struct): + if not jitlog_enabled(): + return + # addr is either a number (trace_id), or the address + # of the descriptor. for entries it is a the trace_id, + # for any label/bridge entry the addr is the address + list = [MARK_JITLOG_COUNTER, encode_le_addr(struct.number), + struct.type, encode_le_64bit(struct.i)] + content = ''.join(list) + jitlog_write_marked(content, len(content)) + +class JitLogger(object): + def __init__(self, cpu=None): + self.cpu = cpu + self.memo = {} + self.trace_id = -1 + self.metainterp_sd = None + # legacy + self.logger_ops = None + self.logger_noopt = None + + def setup_once(self): + if jitlog_enabled(): + return + jitlog_try_init_using_env() + if not jitlog_enabled(): + return + blob = assemble_header() + jitlog_write_marked(MARK_JITLOG_HEADER + blob, len(blob) + 1) + + def finish(self): + jitlog_teardown() + + def start_new_trace(self, metainterp_sd, faildescr=None, entry_bridge=False): + # even if the logger is not enabled, increment the trace id + self.trace_id += 1 + if not jitlog_enabled(): + return + self.metainterp_sd = metainterp_sd + content = [encode_le_addr(self.trace_id)] + if faildescr: + content.append(encode_str('bridge')) + descrnmr = compute_unique_id(faildescr) + content.append(encode_le_addr(descrnmr)) + else: + content.append(encode_str('loop')) + content.append(encode_le_addr(int(entry_bridge))) + self._write_marked(MARK_START_TRACE, ''.join(content)) + + def trace_aborted(self): + if not jitlog_enabled(): + return + self._write_marked(MARK_ABORT_TRACE, encode_le_64bit(self.trace_id)) + + def _write_marked(self, mark, line): + if not we_are_translated(): + assert jitlog_enabled() + jitlog_write_marked(mark + line, len(line) + 1) + + def log_jit_counter(self, struct): + _log_jit_counter(struct) + + def log_trace(self, tag, metainterp_sd, mc, memo=None): + if not jitlog_enabled(): + return EMPTY_TRACE_LOG + assert self.metainterp_sd is not None + if memo is None: + memo = {} + return LogTrace(tag, memo, self.metainterp_sd, mc, self) + + def log_patch_guard(self, descr_number, addr): + if not jitlog_enabled(): + return + le_descr_number = encode_le_addr(descr_number) + le_addr = encode_le_addr(addr) + lst = [le_descr_number, le_addr] + self._write_marked(MARK_STITCH_BRIDGE, ''.join(lst)) + +class BaseLogTrace(object): + def write_trace(self, trace): + return None + + def write(self, args, ops, ops_offset={}): + return None + +EMPTY_TRACE_LOG = BaseLogTrace() + +class PrefixCompressor(object): + def __init__(self, count): + self.prefixes = [None] * count + self.written_prefixes = [None] * count + + def get_last(self, index): + return self.prefixes[index] + + def get_last_written(self, index): + return self.written_prefixes[index] + + def compress(self, index, string): + assert string is not None + last = self.get_last(index) + if last is None: + self.prefixes[index] = string + return None + cp = commonprefix(last, string) + if len(cp) <= 1: # prevent very small common prefixes (like "/") + self.prefixes[index] = string + return None + return cp + + + def write(self, log, index, prefix): + # we have a new prefix + log._write_marked(MARK_COMMON_PREFIX, chr(index) \ + + encode_str(prefix)) + self.written_prefixes[index] = prefix + +def encode_merge_point(log, compressor, values): + line = [] + unrolled = unrolling_iterable(values) + i = 0 + for value in unrolled: + line.append(value.encode(log,i,compressor)) + i += 1 + return ''.join(line) + + +class LogTrace(BaseLogTrace): + def __init__(self, tag, memo, metainterp_sd, mc, logger): + self.memo = memo + self.metainterp_sd = metainterp_sd + self.ts = None + if self.metainterp_sd is not None: + self.ts = metainterp_sd.cpu.ts + self.tag = tag + self.mc = mc + self.logger = logger + self.common_prefix = None + + def write_trace(self, trace): + ops = [] + i = trace.get_iter() + while not i.done(): + ops.append(i.next()) + self.write(i.inputargs, ops) + + def write(self, args, ops, ops_offset={}): + log = self.logger + log._write_marked(self.tag, encode_le_64bit(self.logger.trace_id)) + + # input args + str_args = [self.var_to_str(arg) for arg in args] + string = encode_str(','.join(str_args)) + log._write_marked(MARK_INPUT_ARGS, string) + + # assembler address (to not duplicate it in write_code_dump) + if self.mc is not None: + absaddr = self.mc.absolute_addr() + rel = self.mc.get_relative_pos() + # packs <start addr> <end addr> as two unsigend longs + le_addr1 = encode_le_addr(absaddr) + le_addr2 = encode_le_addr(absaddr + rel) + log._write_marked(MARK_ASM_ADDR, le_addr1 + le_addr2) + for i,op in enumerate(ops): + if rop.DEBUG_MERGE_POINT == op.getopnum(): + self.encode_debug_info(op) + continue + mark, line = self.encode_op(op) + log._write_marked(mark, line) + self.write_core_dump(ops, i, op, ops_offset) + + self.memo = {} + + def encode_once(self): + pass + + def encode_debug_info(self, op): + # the idea is to write the debug merge point as it's own well known + # tag. Compression for common prefixes is implemented: + + log = self.logger + jd_sd = self.metainterp_sd.jitdrivers_sd[op.getarg(0).getint()] + if not jd_sd.warmstate.get_location: + return + values = jd_sd.warmstate.get_location(op.getarglist()[3:]) + if values is None: + # indicates that this function is not provided to the jit driver + return + types = jd_sd.warmstate.get_location_types + + if self.common_prefix is None: + # first time visiting a merge point + # setup the common prefix + self.common_prefix = PrefixCompressor(len(types)) + encoded_types = [] + for i, (semantic_type, generic_type) in enumerate(types): + encoded_types.append(chr(semantic_type)) + encoded_types.append(generic_type) + count = encode_le_16bit(len(types)) + log._write_marked(MARK_INIT_MERGE_POINT, count + ''.join(encoded_types)) + + # the types have already been written + encoded = encode_merge_point(log, self.common_prefix, values) + log._write_marked(MARK_MERGE_POINT, encoded) + + def encode_op(self, op): + """ an operation is written as follows: + <marker> <opid (16 bit)> \ + <len (32 bit)> \ + <res_val>,<arg_0>,...,<arg_n>,<descr> + The marker indicates if the last argument is + a descr or a normal argument. + """ + str_args = [self.var_to_str(arg) for arg in op.getarglist()] + descr = op.getdescr() + le_opnum = encode_le_16bit(op.getopnum()) + str_res = self.var_to_str(op) + line = ','.join([str_res] + str_args) + if descr: + descr_str = descr.repr_of_descr() + line = line + ',' + descr_str + string = encode_str(line) + descr_number = compute_unique_id(descr) + le_descr_number = encode_le_addr(descr_number) + return MARK_RESOP_DESCR, le_opnum + string + le_descr_number + else: + string = encode_str(line) + return MARK_RESOP, le_opnum + string + + + def write_core_dump(self, operations, i, op, ops_offset): + if self.mc is None: + return + + op2 = None + j = i+1 + # find the next op that is in the offset hash + while j < len(operations): + op2 = operations[j] + if op in ops_offset: + break + j += 1 + + # this op has no known offset in the machine code (it might be + # a debug operation) + if op not in ops_offset: + return + # there is no well defined boundary for the end of the + # next op in the assembler + if op2 is not None and op2 not in ops_offset: + return + dump = [] + + start_offset = ops_offset[op] + assert start_offset >= 0 + # end offset is either the last pos in the assembler + # or the offset of op2 + if op2 is None: + end_offset = self.mc.get_relative_pos() + else: + end_offset = ops_offset[op2] + + count = end_offset - start_offset + dump = self.copy_core_dump(self.mc.absolute_addr(), start_offset, count) + offset = encode_le_16bit(start_offset) + edump = encode_str(dump) + self.logger._write_marked(MARK_ASM, offset + edump) + + def copy_core_dump(self, addr, offset=0, count=-1): + dump = [] + src = rffi.cast(rffi.CCHARP, addr) + end = self.mc.get_relative_pos() + if count != -1: + end = offset + count + for p in range(offset, end): + dump.append(src[p]) + return ''.join(dump) + + def var_to_str(self, arg): + try: + mv = self.memo[arg] + except KeyError: + mv = len(self.memo) + self.memo[arg] = mv + if isinstance(arg, ConstInt): + if self.metainterp_sd and int_could_be_an_address(arg.value): + addr = arg.getaddr() + name = self.metainterp_sd.get_name_from_address(addr) + if name: + return 'ConstClass(' + name + ')' + return str(arg.value) + elif self.ts is not None and isinstance(arg, self.ts.ConstRef): + if arg.value: + return 'ConstPtr(ptr' + str(mv) + ')' + return 'ConstPtr(null)' + if isinstance(arg, ConstFloat): + return str(arg.getfloat()) + elif arg is None: + return 'None' + elif arg.is_vector(): + return 'v' + str(mv) + elif arg.type == 'i': + return 'i' + str(mv) + elif arg.type == 'r': + return 'p' + str(mv) + elif arg.type == 'f': + return 'f' + str(mv) + else: + return '?' + +def int_could_be_an_address(x): + if we_are_translated(): + x = rffi.cast(lltype.Signed, x) # force it + return not (-32768 <= x <= 32767) + else: + return isinstance(x, llmemory.AddressAsInt) diff --git a/rpython/rlib/rjitlog/src/rjitlog.c b/rpython/rlib/rjitlog/src/rjitlog.c new file mode 100644 --- /dev/null +++ b/rpython/rlib/rjitlog/src/rjitlog.c @@ -0,0 +1,91 @@ +#define _GNU_SOURCE 1 + +#ifdef RPYTHON_LL2CTYPES +/* only for testing: ll2ctypes sets RPY_EXTERN from the command-line */ +#ifndef RPY_EXTERN +#define RPY_EXTERN RPY_EXPORTED +#endif +#ifdef _WIN32 +#define RPY_EXPORTED __declspec(dllexport) +#else +#define RPY_EXPORTED extern __attribute__((visibility("default"))) +#endif +#else +#include "common_header.h" +#include "structdef.h" +#include "src/threadlocal.h" +#include "rjitlog.h" +#endif + +#include <string.h> +#include <stdlib.h> +#include <stdio.h> +#include <sys/types.h> +#include <sys/stat.h> +#include <fcntl.h> +#include <unistd.h> +#include <errno.h> + +static int jitlog_fd = -1; +static int jitlog_ready = 0; + +RPY_EXTERN +int jitlog_enabled() +{ + return jitlog_ready; +} + +RPY_EXTERN +void jitlog_try_init_using_env(void) { + if (jitlog_ready) { return; } + + char *filename = getenv("JITLOG"); + + if (filename && filename[0]) { + // mode is 775 + mode_t mode = S_IRWXU | S_IRWXG | S_IROTH | S_IXOTH; + jitlog_fd = open(filename, O_WRONLY | O_CREAT | O_TRUNC, mode); + if (jitlog_fd == -1) { + dprintf(2, "could not open '%s': ", filename); + perror(NULL); + exit(-1); + } + } else { + jitlog_ready = 0; + return; + } +#ifndef _WIN32 + unsetenv("JITLOG"); +#else + putenv("JITLOG="); +#endif + jitlog_ready = 1; +} + +RPY_EXTERN +char *jitlog_init(int fd) +{ + jitlog_fd = fd; + jitlog_ready = 1; + return NULL; +} + +RPY_EXTERN _______________________________________________ pypy-commit mailing list pypy-commit@python.org https://mail.python.org/mailman/listinfo/pypy-commit