Re: MPS: profiler

[Gerd Möllmann]

Ihor Radchenko <yantar92@posteo.net> writes:

> Gerd Möllmann <gerd.moellmann@gmail.com> writes:
>
>>>>> Steps to reproduce:
>>>>> 
>>>>> 1. emacs -Q doc/misc/org.org
>>>>> 2. M-x profiler-start RET cpu RET
>>>>> 3. M-: (org-element-parse-buffer) RET
>> ...
>> Thanks, that's the latest and greatest. I'm afraid that means it's time
>> to get out the debugger :-).

> Thread 1 "emacs" received signal SIGSEGV, Segmentation fault.
> 0x00005555558b53d6 in PSEUDOVECTORP (a=0x7fffe6dde715, code=32) at 
> /home/yantar92/Git/emacs/src/lisp.h:1104
> 1104           && ((XUNTAG (a, Lisp_Vectorlike, union vectorlike_header)->size
> (gdb) bt
> #0  0x00005555558b53d6 in PSEUDOVECTORP (a=0x7fffe6dde715, code=32) at 
> /home/yantar92/Git/emacs/src/lisp.h:1104
> #1  0x00005555558b567f in CLOSUREP (a=0x7fffe6dde715) at 
> /home/yantar92/Git/emacs/src/lisp.h:3368
> #2  0x00005555558b5b80 in trace_hash (trace=0x555556329400, depth=16) at 
> profiler.c:189
> #3  0x00005555558b5eab in record_backtrace (plog=0x555555fd0960 <cpu>, 
> count=2) at profiler.c:291
> #4  0x00005555558b60fd in add_sample (plog=0x555555fd0960 <cpu>, count=2) at 
> profiler.c:353
> #5  0x00005555558b6153 in handle_profiler_signal (signal=27) at profiler.c:396
> #6  0x0000555555777704 in deliver_process_signal (sig=27, 
> handler=0x5555558b6104 <handle_profiler_signal>) at sysdep.c:1758
> #7  0x00005555558b6175 in deliver_profiler_signal (signal=27) at 
> profiler.c:402
> #8  0x00007ffff5855470 in <signal handler called> () at /lib64/libc.so.6
> #9  0x00007ffff5922d07 in mprotect () at /lib64/libc.so.6

4. MPS tries to un-mprotect something and receives a signal. From the
the profiler.c frames, I'd say it's a SIGPROF. And while handling the
signal, we are doing Lisp stuff. All while MPS is currently trying to
scan.

Hm, I must admit that I don't know how that's supposed to work ATM. Very
strictly speaking, a signal handler is not allowed to do very much...
Or maybe the problem is that the signal gets delivered to Emacs in the
first place?

(AFAIK, MPS doesn't use signals on macOS, but Mach exceptions, so things
probably work pretty different here, like on Windows.)

I guess we need some Linux expert here.

> #10 0x000055555595c498 in ProtSet (base=0x7fffe2d86000, limit=<optimized 
> out>, mode=0) at protix.c:105
> #11 0x000055555594f7dd in shieldProtLower 
> (shield=shield@entry=0x7ffff7fc2700, seg=seg@entry=0x7fffe8001988, 
> mode=mode@entry=3) at shield.c:305
> #12 0x0000555555950417 in ShieldExpose (arena=arena@entry=0x7ffff7fc2000, 
> seg=seg@entry=0x7fffe8001988) at shield.c:737
> #13 0x000055555595f045 in amcSegFix (seg=0x7fffe8001988, ss=0x7fffffffa690, 
> refIO=0x7fffffffa0f8) at poolamc.c:1594
> #14 0x0000555555948d31 in SegFix (seg=0x7fffe8001988, ss=0x7fffffffa690, 
> refIO=0x7fffffffa0f8) at seg.c:793
> #15 0x00005555559550c0 in _mps_fix2 (mps_ss=0x7fffffffa698, 
> mps_ref_io=0x7fffffffa160) at trace.c:1433
> #16 0x00005555558b83af in fix_lisp_obj (ss=0x7fffffffa698, 
> pobj=0x7fffeb08b038) at igc.c:675

3. We are trying to "fix" a single Lisp_Object.

> #17 0x00005555558b86b5 in fix_array (ss=0x7fffffffa698, array=0x7fffeb08b038, 
> n=4) at igc.c:801
> #18 0x00005555558babf6 in fix_vectorlike (ss=0x7fffffffa698, 
> v=0x7fffeb08b030) at igc.c:1554
> #19 0x00005555558bc692 in fix_vector (ss=0x7fffffffa698, v=0x7fffeb08b030) at 
> igc.c:2086
> #20 0x00005555558ba757 in dflt_scan_obj (ss=0x7fffffffa698, 
> base_start=0x7fffeb08b028, base_limit=0x7fffeb08c608, closure=0x0) at 
> igc.c:1481
> #21 0x00005555558baac4 in dflt_scanx (ss=0x7fffffffa698, 
> base_start=0x7fffeb08b000, base_limit=0x7fffeb08c608, closure=0x0) at 
> igc.c:1531
> #22 0x00005555558bab63 in dflt_scan (ss=0x7fffffffa698, 
> base_start=0x7fffeb08b000, base_limit=0x7fffeb08c608) at igc.c:1542
> #23 0x000055555595568f in TraceScanFormat (ss=ss@entry=0x7fffffffa690, 
> base=base@entry=0x7fffeb08b000, limit=limit@entry=0x7fffeb08c608) at 
> trace.c:1539
> #24 0x000055555595f609 in amcSegScan (totalReturn=0x7fffffffa68c,
> seg=0x7fffe8289870, ss=0x7fffffffa690) at poolamc.c:1427

2. MPS starts scanning the default pool and invokes our dflt_scan
function.

> #25 0x0000555555948c6f in SegScan 
> (totalReturn=totalReturn@entry=0x7fffffffa68c, seg=seg@entry=0x7fffe8289870, 
> ss=ss@entry=0x7fffffffa690) at seg.c:775
> #26 0x0000555555954ae1 in traceScanSegRes (ts=ts@entry=1, rank=rank@entry=1, 
> arena=arena@entry=0x7ffff7fc2000, seg=seg@entry=0x7fffe8289870) at 
> trace.c:1205
> #27 0x0000555555954beb in traceScanSeg (ts=ts@entry=1, rank=1, 
> arena=arena@entry=0x7ffff7fc2000, seg=seg@entry=0x7fffe8289870) at 
> trace.c:1267
> #28 0x0000555555954d63 in TraceSegAccess (arena=arena@entry=0x7ffff7fc2000, 
> seg=seg@entry=0x7fffe8289870, mode=mode@entry=1) at trace.c:1320
> #29 0x000055555594959b in SegWholeAccess (seg=0x7fffe8289870, 
> arena=0x7ffff7fc2000, addr=0x7fffeb08c590, mode=1, context=0x7fffffffa8d0) at 
> seg.c:1262
> #30 0x0000555555948309 in SegAccess
>     (seg=0x7fffe8289870, arena=arena@entry=0x7ffff7fc2000, 
> addr=addr@entry=0x7fffeb08c590, mode=1, context=context@entry=0x7fffffffa8d0) 
> at seg.c:723
> #31 0x0000555555928f51 in ArenaAccess (addr=0x7fffeb08c590, mode=<optimized 
> out>, mode@entry=3, context=context@entry=0x7fffffffa8d0) at global.c:671
> #32 0x000055555595c6e2 in sigHandle (sig=<optimized out>, 
> info=0x7fffffffabf0, uap=0x7fffffffaac0) at protsgix.c:97
> #33 0x00007ffff5855470 in <signal handler called> () at /lib64/libc.so.6

1. So here in copy_intervals happens something that invokes MPS. Not 100%
sure but it looks to me that it is because we hit an MPS barrier
(mprotected area).

> #34 0x00005555558a1dd8 in copy_intervals (tree=0x7fffe651f500, start=587977, 
> length=11) at intervals.c:2247
> #35 0x00005555558a1ee6 in copy_intervals_to_string (string=0x7fffeae8dfb4, 
> buffer=0x7fffe4275e90, position=587977, length=11) at intervals.c:2272
> #36 0x0000555555800168 in make_buffer_string_both (start=587977, 
> start_byte=588047, end=587988, end_byte=588058, props=true) at editfns.c:1615
> #37 0x00005555557ffe53 in make_buffer_string (start=587977, end=587988, 
> props=true) at editfns.c:1554
> #38 0x0000555555800302 in Fbuffer_substring (start=0x23e326, end=0x23e352) at 
> editfns.c:1666
> #39 0x0000555555870a1d in exec_byte_code (fun=0x7fffe446a465, 
> args_template=771, nargs=3, args=0x7fffe2200928) at bytecode.c:1516
> --Type <RET> for more, q to quit, c to continue without paging--c
> #40 0x00005555558158df in funcall_lambda (fun=0x7fffe5b0842d, nargs=0, 
> arg_vector=0x7fffffffb880) at eval.c:3270
> #41 0x0000555555815762 in apply_lambda (fun=0x7fffe5b0842d, args=0x0, 
> count=...) at eval.c:3233
> #42 0x0000555555813c6d in eval_sub (form=0x7fffe6dde54b) at eval.c:2663
> #43 0x0000555555813170 in Feval (form=0x7fffe6dde54b, lexical=0x30) at 
> eval.c:2475
> #44 0x0000555555815303 in funcall_subr (subr=0x555555f2d380 <Seval>, 
> numargs=2, args=0x7fffe22001b0) at eval.c:3181
> #45 0x000055555586d392 in exec_byte_code (fun=0x7fffe3170b85, 
> args_template=513, nargs=2, args=0x7fffe2200320) at bytecode.c:827
> #46 0x00005555558158df in funcall_lambda (fun=0x7fffe6dde75d, nargs=0, 
> arg_vector=0x7fffffffc110) at eval.c:3270
> #47 0x0000555555814d61 in funcall_general (fun=0x7fffe6dde75d, numargs=0, 
> args=0x7fffffffc110) at eval.c:3062
> #48 0x0000555555814fc6 in Ffuncall (nargs=1, args=0x7fffffffc108) at 
> eval.c:3111
> #49 0x000055555580da20 in call0 (fn=0x7fffe6dde75d) at 
> /home/yantar92/Git/emacs/src/lisp.h:3559
> #50 0x0000555555810cc9 in Fhandler_bind_1 (nargs=3, args=0x7fffe2200128) at 
> eval.c:1487
> #51 0x000055555581552d in funcall_subr (subr=0x555555f2d240 
> <Shandler_bind_1>, numargs=3, args=0x7fffe2200128) at eval.c:3202
> #52 0x000055555586d392 in exec_byte_code (fun=0x7fffe31696c5, 
> args_template=1025, nargs=4, args=0x7fffffffc990) at bytecode.c:827
> #53 0x00005555558158df in funcall_lambda (fun=0x7fffe31696c5, nargs=4, 
> arg_vector=0x7fffffffc970) at eval.c:3270
> #54 0x0000555555814d61 in funcall_general (fun=0x7fffe31696c5, numargs=4, 
> args=0x7fffffffc970) at eval.c:3062
> #55 0x0000555555814fc6 in Ffuncall (nargs=5, args=0x7fffffffc968) at 
> eval.c:3111
> #56 0x000055555580a532 in Ffuncall_interactively (nargs=5, 
> args=0x7fffffffc968) at callint.c:250
> #57 0x000055555581552d in funcall_subr (subr=0x555555f2ca80 
> <Sfuncall_interactively>, numargs=5, args=0x7fffffffc968) at eval.c:3202
> #58 0x0000555555814d15 in funcall_general (fun=0x555555f2ca85 
> <Sfuncall_interactively+5>, numargs=5, args=0x7fffffffc968) at eval.c:3058
> #59 0x0000555555814fc6 in Ffuncall (nargs=6, args=0x7fffffffc960) at 
> eval.c:3111
> #60 0x000055555581446d in Fapply (nargs=3, args=0x7fffffffcbf0) at eval.c:2783
> #61 0x000055555580a92c in Fcall_interactively (function=0x2aaa8d1c2b08, 
> record_flag=0x0, keys=0x7fffe6d46865) at callint.c:342
> #62 0x0000555555815339 in funcall_subr (subr=0x555555f2cac0 
> <Scall_interactively>, numargs=3, args=0x7fffe2200070) at eval.c:3183
> #63 0x000055555586d392 in exec_byte_code (fun=0x7fffe36e5c7d, 
> args_template=1025, nargs=1, args=0x7fffffffd350) at bytecode.c:827
> #64 0x00005555558158df in funcall_lambda (fun=0x7fffe36e5c7d, nargs=1, 
> arg_vector=0x7fffffffd348) at eval.c:3270
> #65 0x0000555555814d61 in funcall_general (fun=0x7fffe36e5c7d, numargs=1, 
> args=0x7fffffffd348) at eval.c:3062
> #66 0x0000555555814fc6 in Ffuncall (nargs=2, args=0x7fffffffd340) at 
> eval.c:3111
> #67 0x000055555574d687 in command_loop_1 () at keyboard.c:1551
> #68 0x00005555558113c9 in internal_condition_case (bfun=0x55555574ce24 
> <command_loop_1>, handlers=0x90, hfun=0x55555574c355 <cmd_error>) at 
> eval.c:1622
> #69 0x000055555574ca71 in command_loop_2 (handlers=0x90) at keyboard.c:1169
> #70 0x0000555555810872 in internal_catch (tag=0x12300, func=0x55555574ca47 
> <command_loop_2>, arg=0x90) at eval.c:1301
> #71 0x000055555574ca03 in command_loop () at keyboard.c:1147
> #72 0x000055555574bef7 in recursive_edit_1 () at keyboard.c:755
> #73 0x000055555574c0a3 in Frecursive_edit () at keyboard.c:838
> #74 0x00005555557482fc in main (argc=2, argv=0x7fffffffd838) at emacs.c:2643