bug#13573: 24.3.50; src/profiler.c:123: Emacs fatal error: assertion failed: EQ (log->next_free, make_number (i))

[Dmitry Antipov]

Crash caused by profiler when byte-force-recompile all Lisp sources.

Found in bzr revision 111614 and looks regular.

Steps to reproduce:

./src/emacs -Q
M-x profiler-start RET cpu RET
M-x byte-force-recompile RET lisp RET

--enable-checking is enabled, the crash is:

src/profiler.c:123: Emacs fatal error: assertion failed: EQ (log->next_free, 
make_number (i))

#0  0x000000342a00eedb in raise (sig=sig@entry=6) at 
../nptl/sysdeps/unix/sysv/linux/pt-raise.c:41
#1  0x00000000005226c8 in terminate_due_to_signal (sig=sig@entry=6, 
backtrace_limit=backtrace_limit@entry=2147483647)
    at src/emacs.c:343
#2  0x0000000000591474 in die (msg=msg@entry=0x7202b0 "assertion failed: EQ 
(log->next_free, make_number (i))", file=file@entry=
    0x7200f8 "src/profiler.c", line=line@entry=123)
    at src/alloc.c:6563
#3  0x00000000006266b1 in evict_lower_half (log=0xd493f0) at src/profiler.c:123
#4  record_backtrace (log=0xd493f0, count=1) at src/profiler.c:149
#5  0x0000000000543685 in deliver_process_signal (sig=27, handler=0x626bd0 
<handle_profiler_signal>)
    at src/sysdep.c:1595
#6  <signal handler called>
#7  exec_byte_code (bytestr=..., vector=..., maxdepth=..., args_template=..., 
nargs=4611686018645491712, args=0x7fffffffffffffff,
    args@entry=0x7fff5f2f8770) at src/bytecode.c:747
#8  0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=1, 
arg_vector=arg_vector@entry=0x7fff5f2f8770)
    at src/eval.c:2841
#9  0x00000000005b1dfb in Ffuncall (nargs=2, args=0x7fff5f2f8768) at 
src/eval.c:2736
#10 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f89b8) at src/bytecode.c:898
#11 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=2, 
arg_vector=arg_vector@entry=0x7fff5f2f89b8)
    at src/eval.c:2841
#12 0x00000000005b1dfb in Ffuncall (nargs=3, args=0x7fff5f2f89b0) at 
src/eval.c:2736
#13 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f8be8) at src/bytecode.c:898
#14 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=5, 
arg_vector=arg_vector@entry=0x7fff5f2f8be8)
    at src/eval.c:2841
#15 0x00000000005b1dfb in Ffuncall (nargs=6, args=0x7fff5f2f8be0) at 
src/eval.c:2736
#16 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f8e28) at src/bytecode.c:898
#17 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=2, 
arg_vector=arg_vector@entry=0x7fff5f2f8e28)
    at src/eval.c:2841
#18 0x00000000005b1dfb in Ffuncall (nargs=3, args=0x7fff5f2f8e20) at 
src/eval.c:2736
#19 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9050) at src/bytecode.c:898
#20 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=5, 
arg_vector=arg_vector@entry=0x7fff5f2f9050)
    at src/eval.c:2841
#21 0x00000000005b1dfb in Ffuncall (nargs=6, args=0x7fff5f2f9048) at 
src/eval.c:2736
#22 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9280) at src/bytecode.c:898
#23 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=6, 
arg_vector=arg_vector@entry=0x7fff5f2f9280)
    at src/eval.c:2841
#24 0x00000000005b1dfb in Ffuncall (nargs=7, args=0x7fff5f2f9278) at 
src/eval.c:2736
#25 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f94b0) at src/bytecode.c:898
#26 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=5, 
arg_vector=arg_vector@entry=0x7fff5f2f94b0)
    at src/eval.c:2841
#27 0x00000000005b1dfb in Ffuncall (nargs=6, args=0x7fff5f2f94a8) at 
src/eval.c:2736
#28 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9710) at src/bytecode.c:898
#29 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=5, 
arg_vector=arg_vector@entry=0x7fff5f2f9710)
    at src/eval.c:2841
#30 0x00000000005b1dfb in Ffuncall (nargs=6, args=0x7fff5f2f9708) at 
src/eval.c:2736
#31 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9940) at src/bytecode.c:898
#32 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=1, 
arg_vector=arg_vector@entry=0x7fff5f2f9940)
    at src/eval.c:2841
#33 0x00000000005b1dfb in Ffuncall (nargs=2, args=0x7fff5f2f9938) at 
src/eval.c:2736
#34 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9b08) at src/bytecode.c:898
#35 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=1, 
arg_vector=arg_vector@entry=0x7fff5f2f9b08)
    at src/eval.c:2841
#36 0x00000000005b1dfb in Ffuncall (nargs=2, args=0x7fff5f2f9b00) at 
src/eval.c:2736
#37 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9cd8) at src/bytecode.c:898
#38 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=1, 
arg_vector=arg_vector@entry=0x7fff5f2f9cd8)
    at src/eval.c:2841
#39 0x00000000005b1dfb in Ffuncall (nargs=2, args=0x7fff5f2f9cd0) at 
src/eval.c:2736
#40 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2f9ea0) at src/bytecode.c:898
#41 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=0, 
arg_vector=arg_vector@entry=0x7fff5f2f9ea0)
    at src/eval.c:2841
#42 0x00000000005b1dfb in Ffuncall (nargs=1, args=0x7fff5f2f9e98) at 
src/eval.c:2736
#43 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fa058) at src/bytecode.c:898
#44 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=0, 
arg_vector=arg_vector@entry=0x7fff5f2fa058)
    at src/eval.c:2841
#45 0x00000000005b1dfb in Ffuncall (nargs=1, args=0x7fff5f2fa050) at 
src/eval.c:2736
#46 0x00000000005b12e5 in eval_sub (form=..., form@entry=...) at src/eval.c:2012
#47 0x00000000005b48e6 in internal_lisp_condition_case (var=..., bodyform=..., 
handlers=...)
    at src/eval.c:1147
#48 0x00000000005f9633 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fa550) at src/bytecode.c:1094
#49 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=1, 
arg_vector=arg_vector@entry=0x7fff5f2fa550)
    at src/eval.c:2841
#50 0x00000000005b1dfb in Ffuncall (nargs=2, args=0x7fff5f2fa548) at 
src/eval.c:2736
#51 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fa770) at src/bytecode.c:898
#52 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=2, 
arg_vector=arg_vector@entry=0x7fff5f2fa770)
    at src/eval.c:2841
#53 0x00000000005b1dfb in Ffuncall (nargs=3, args=0x7fff5f2fa768) at 
src/eval.c:2736
#54 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fa958) at src/bytecode.c:898
#55 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=3, 
arg_vector=arg_vector@entry=0x7fff5f2fa958)
    at src/eval.c:2841
#56 0x00000000005b1dfb in Ffuncall (nargs=4, args=0x7fff5f2fa950) at 
src/eval.c:2736
#57 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fab20) at src/bytecode.c:898
#58 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=0, 
arg_vector=arg_vector@entry=0x7fff5f2fab20)
    at src/eval.c:2841
#59 0x00000000005b1dfb in Ffuncall (nargs=1, args=0x7fff5f2fab18) at 
src/eval.c:2736
#60 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2facd8) at src/bytecode.c:898
#61 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=0, 
arg_vector=arg_vector@entry=0x7fff5f2facd8)
    at src/eval.c:2841
#62 0x00000000005b1dfb in Ffuncall (nargs=1, args=0x7fff5f2facd0) at 
src/eval.c:2736
#63 0x00000000005b12e5 in eval_sub (form=..., form@entry=...) at src/eval.c:2012
#64 0x00000000005b48e6 in internal_lisp_condition_case (var=..., bodyform=..., 
handlers=...)
    at src/eval.c:1147
#65 0x00000000005f9633 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fb1e8) at src/bytecode.c:1094
#66 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=3, 
arg_vector=arg_vector@entry=0x7fff5f2fb1e8)
    at src/eval.c:2841
#67 0x00000000005b1dfb in Ffuncall (nargs=4, args=0x7fff5f2fb1e0) at 
src/eval.c:2736
#68 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fb3f8) at src/bytecode.c:898
#69 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=1, 
arg_vector=arg_vector@entry=0x7fff5f2fb3f8)
    at src/eval.c:2841
#70 0x00000000005b1dfb in Ffuncall (nargs=nargs@entry=2, 
args=args@entry=0x7fff5f2fb3f0)
    at src/eval.c:2736
#71 0x00000000005aeaa5 in Fcall_interactively (function=..., record_flag=..., 
keys=...)
    at src/callint.c:852
#72 0x00000000005b1fcc in Ffuncall (nargs=nargs@entry=4, 
args=args@entry=0x7fff5f2fb5c0)
    at src/eval.c:2682
#73 0x00000000005b21b4 in call3 (fn=..., arg1=..., arg1@entry=..., arg2=..., 
arg2@entry=..., arg3=..., arg3@entry=...)
    at src/eval.c:2500
#74 0x0000000000525435 in Fcommand_execute (cmd=..., record_flag=..., keys=..., 
special=...)
    at src/keyboard.c:10237
#75 0x00000000005b1fb6 in Ffuncall (nargs=<optimized out>, args=<optimized 
out>) at src/eval.c:2686
#76 0x00000000005f8d73 in exec_byte_code (bytestr=..., vector=..., 
maxdepth=..., args_template=..., nargs=4611686018645491712, args=
    0x7fffffffffffffff, args@entry=0x7fff5f2fb908) at src/bytecode.c:898
#77 0x00000000005b1955 in funcall_lambda (fun=..., nargs=nargs@entry=2, 
arg_vector=arg_vector@entry=0x7fff5f2fb908)
    at src/eval.c:2841
#78 0x00000000005b1dfb in Ffuncall (nargs=nargs@entry=3, 
args=args@entry=0x7fff5f2fb900)
    at src/eval.c:2736
#79 0x00000000005b2ece in Fapply (nargs=nargs@entry=2, 
args=args@entry=0x7fff5f2fb9c0)
    at src/eval.c:2209
#80 0x00000000005b22ee in apply1 (fn=..., arg=..., arg@entry=...) at 
src/eval.c:2443
#81 0x00000000005ad9f4 in Fcall_interactively (function=..., record_flag=..., 
keys=...)
    at src/callint.c:377
#82 0x00000000005b1fcc in Ffuncall (nargs=nargs@entry=4, 
args=args@entry=0x7fff5f2fbb60)
    at src/eval.c:2682
#83 0x00000000005b21b4 in call3 (fn=..., arg1=..., arg1@entry=..., arg2=..., 
arg2@entry=..., arg3=..., arg3@entry=...)
    at src/eval.c:2500
#84 0x0000000000525435 in Fcommand_execute (cmd=..., record_flag=..., keys=..., 
special=...)
    at src/keyboard.c:10237
#85 0x00000000005364ed in command_loop_1 () at src/keyboard.c:1587
#86 0x00000000005afdb3 in internal_condition_case (bfun=bfun@entry=0x535ff0 
<command_loop_1>, handlers=..., hfun=hfun@entry=
    0x527fc0 <cmd_error>) at src/eval.c:1193
#87 0x00000000005262fe in command_loop_2 (ignore=..., ignore@entry=...) at 
src/keyboard.c:1174
#88 0x00000000005afc90 in internal_catch (tag=..., func=func@entry=0x5262e0 
<command_loop_2>, arg=...)
    at src/eval.c:964
#89 0x000000000052794e in command_loop () at src/keyboard.c:1153
#90 recursive_edit_1 () at src/keyboard.c:786
#91 0x0000000000527cec in Frecursive_edit () at src/keyboard.c:850
#92 0x000000000041823a in main (argc=2, argv=<optimized out>) at 
src/emacs.c:1556

Lisp Backtrace:
"byte-optimize-lapcode" (0x5f2f8770)
"byte-compile-out-toplevel" (0x5f2f89b8)
"byte-compile-top-level" (0x5f2f8be8)
"byte-compile-lambda" (0x5f2f8e28)
"byte-compile-file-form-defmumble" (0x5f2f9050)
0x2758468 PVEC_COMPILED
0x2758498 PVEC_COMPILED
0x27584c8 PVEC_COMPILED
"byte-compile-file-form-defalias" (0x5f2f9940)
"byte-compile-file-form" (0x5f2f9b08)
"byte-compile-toplevel-file-form" (0x5f2f9cd8)
0x3507dd8 PVEC_COMPILED
0x3041468 PVEC_COMPILED
"funcall" (0x5f2fa050)
"byte-compile-from-buffer" (0x5f2fa550)
"byte-compile-file" (0x5f2fa770)
"byte-recompile-file" (0x5f2fa958)
0x260c1d8 PVEC_COMPILED
0x260c208 PVEC_COMPILED
"funcall" (0x5f2facd0)
"byte-recompile-directory" (0x5f2fb1e8)
"byte-force-recompile" (0x5f2fb3f8)
"call-interactively" (0x5f2fb5c8)
"command-execute" (0x5f2fb710)
"execute-extended-command" (0x5f2fb908)
"call-interactively" (0x5f2fbb68)

Dmitry