From 03d418dcd339c8878186fcc8e165b62289d3d17c Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Tue, 5 Mar 2013 11:48:47 +0100 Subject: Tmp --- erts/emulator/sys/win32/sys_time.c | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/erts/emulator/sys/win32/sys_time.c b/erts/emulator/sys/win32/sys_time.c index 2f2dfc8197..8775b6a24d 100644 --- a/erts/emulator/sys/win32/sys_time.c +++ b/erts/emulator/sys/win32/sys_time.c @@ -63,6 +63,7 @@ static SysHrTime wrap = 0; static DWORD last_tick_count = 0; +static erts_smp_spinlock_t wrap_lock; /* Getting timezone information is a heavy operation, so we want to do this only once */ @@ -82,6 +83,7 @@ sys_init_time(void) static_tzi.DaylightDate.wMonth != 0) { have_static_tzi = 1; } + erts_smp_spinlock_init(&wrap_lock, "sys_gethrtime"); return 1; } @@ -367,11 +369,15 @@ SysHrTime sys_gethrtime(void) { DWORD ticks = (SysHrTime) (GetTickCount() & 0x7FFFFFFF); + SysHrTime res; + erts_smp_spin_lock(&wrap_lock); if (ticks < (SysHrTime) last_tick_count) { wrap += LL_LITERAL(1) << 31; } last_tick_count = ticks; - return ((((LONGLONG) ticks) + wrap) * LL_LITERAL(1000000)); + res = ((((LONGLONG) ticks) + wrap) * LL_LITERAL(1000000)); + erts_smp_spin_unlock(&wrap_lock); + return res } clock_t -- cgit v1.2.3 From be0da3e4417176421c24a226765eb07752f8635c Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Mon, 11 Mar 2013 15:27:26 +0100 Subject: Intermediate code with lock on gettickcount() --- erts/emulator/beam/erl_lock_check.c | 5 +++ erts/emulator/sys/win32/sys_time.c | 62 ++++++++++++++++++++++++++++++------- 2 files changed, 56 insertions(+), 11 deletions(-) diff --git a/erts/emulator/beam/erl_lock_check.c b/erts/emulator/beam/erl_lock_check.c index 69bb4be717..c85c079e73 100644 --- a/erts/emulator/beam/erl_lock_check.c +++ b/erts/emulator/beam/erl_lock_check.c @@ -181,6 +181,11 @@ static erts_lc_lock_order_t erts_lock_order[] = { { "efile_drv dtrace mutex", NULL }, #endif { "mtrace_buf", NULL }, +#ifdef __WIN32__ +#ifdef ERTS_SMP + { "sys_gethrtime", NULL }, +#endif +#endif { "erts_alloc_hard_debug", NULL } }; diff --git a/erts/emulator/sys/win32/sys_time.c b/erts/emulator/sys/win32/sys_time.c index 8775b6a24d..1a33061ef1 100644 --- a/erts/emulator/sys/win32/sys_time.c +++ b/erts/emulator/sys/win32/sys_time.c @@ -63,7 +63,8 @@ static SysHrTime wrap = 0; static DWORD last_tick_count = 0; -static erts_smp_spinlock_t wrap_lock; +static erts_smp_mtx_t wrap_lock; +static ULONGLONG (WINAPI *pGetTickCount64)(void) = NULL; /* Getting timezone information is a heavy operation, so we want to do this only once */ @@ -78,12 +79,31 @@ static int days_in_month[2][13] = { int sys_init_time(void) { + /* + char kernel_dll_name[] = "kernel32"; + HMODULE module; + + module = GetModuleHandle(kernel_dll_name); + pGetTickCount64 = (module != NULL) ? + (ULONGLONG (WINAPI *)(void)) + GetProcAddress(module,"GetTickCount64") : + NULL; + */ if(GetTimeZoneInformation(&static_tzi) && static_tzi.StandardDate.wMonth != 0 && static_tzi.DaylightDate.wMonth != 0) { have_static_tzi = 1; } - erts_smp_spinlock_init(&wrap_lock, "sys_gethrtime"); + + erts_smp_mtx_init(&wrap_lock, "sys_gethrtime"); + /* + * XXX: Debug - remove me! + */ + if (pGetTickCount64 != NULL) { + fprintf(stderr,"got GetTickCount64!\r\n"); + fflush(stderr); + } + return 1; } @@ -365,19 +385,39 @@ sys_gettimeofday(SysTimeval *tv) EPOCH_JULIAN_DIFF); } +extern int erts_initialized; SysHrTime sys_gethrtime(void) { - DWORD ticks = (SysHrTime) (GetTickCount() & 0x7FFFFFFF); - SysHrTime res; - erts_smp_spin_lock(&wrap_lock); - if (ticks < (SysHrTime) last_tick_count) { - wrap += LL_LITERAL(1) << 31; + if (pGetTickCount64 != NULL) { + return ((SysHrTime) pGetTickCount64()) * LL_LITERAL(1000000); + } else { + DWORD ticks; + SysHrTime res; + erts_smp_mtx_lock(&wrap_lock); + ticks = (SysHrTime) (GetTickCount() & 0x7FFFFFFF); + if (ticks < (SysHrTime) last_tick_count) { + /* Detect a race that should no longer be here... */ + if ((((SysHrTime) last_tick_count) - ((SysHrTime) ticks)) > 1000) { + wrap += LL_LITERAL(1) << 31; + } else { + /* + * XXX Debug: Violates locking order, remove all this, + * after testing! + */ + erts_dsprintf_buf_t *dsbufp = erts_create_logger_dsbuf(); + erts_dsprintf(dsbufp, "Did not wrap when last_tick %d " + "and tick %d", + last_tick_count, ticks); + erts_send_error_to_logger_nogl(dsbufp); + ticks = last_tick_count; + } + } + last_tick_count = ticks; + res = ((((LONGLONG) ticks) + wrap) * LL_LITERAL(1000000)); + erts_smp_mtx_unlock(&wrap_lock); + return res; } - last_tick_count = ticks; - res = ((((LONGLONG) ticks) + wrap) * LL_LITERAL(1000000)); - erts_smp_spin_unlock(&wrap_lock); - return res } clock_t -- cgit v1.2.3 From 0ebffb2b55bd1870bfbe0ea47aa94017d7917084 Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Thu, 2 May 2013 15:48:55 +0200 Subject: Fix faulty rest on error in unicode:characters_to_list --- erts/emulator/beam/erl_unicode.c | 4 +- lib/stdlib/test/unicode_SUITE.erl | 147 +++++++++++++++++++++++++++++++++++++- 2 files changed, 147 insertions(+), 4 deletions(-) diff --git a/erts/emulator/beam/erl_unicode.c b/erts/emulator/beam/erl_unicode.c index ad6f8b993a..e00440b905 100644 --- a/erts/emulator/beam/erl_unicode.c +++ b/erts/emulator/beam/erl_unicode.c @@ -1723,14 +1723,14 @@ static BIF_RETTYPE do_bif_utf8_to_list(Process *p, if (b_sz) { ErlSubBin *sb; Eterm orig; - ERTS_DECLARE_DUMMY(Uint offset); + Uint offset; ASSERT(state != ERTS_UTF8_OK); hp = HAlloc(p, ERL_SUB_BIN_SIZE); sb = (ErlSubBin *) hp; ERTS_GET_REAL_BIN(orig_bin, orig, offset, bitoffs, bitsize); sb->thing_word = HEADER_SUB_BIN; sb->size = b_sz; - sb->offs = num_bytes_to_process + num_processed_bytes; + sb->offs = offset + num_bytes_to_process + num_processed_bytes; sb->orig = orig; sb->bitoffs = bitoffs; sb->bitsize = bitsize; diff --git a/lib/stdlib/test/unicode_SUITE.erl b/lib/stdlib/test/unicode_SUITE.erl index 4055af2741..6106a8c444 100644 --- a/lib/stdlib/test/unicode_SUITE.erl +++ b/lib/stdlib/test/unicode_SUITE.erl @@ -29,7 +29,7 @@ random_lists/1, roundtrips/1, latin1/1, - exceptions/1]). + exceptions/1, binaries_errors/1]). init_per_testcase(Case, Config) when is_atom(Case), is_list(Config) -> Dog=?t:timetrap(?t:minutes(20)), @@ -44,7 +44,7 @@ suite() -> [{ct_hooks,[ts_install_cth]}]. all() -> [utf8_illegal_sequences_bif, utf16_illegal_sequences_bif, random_lists, roundtrips, - latin1, exceptions]. + latin1, exceptions, binaries_errors]. groups() -> []. @@ -61,6 +61,149 @@ init_per_group(_GroupName, Config) -> end_per_group(_GroupName, Config) -> Config. +binaries_errors(Config) when is_list(Config) -> + setlimit(10), + ex_binaries_errors_utf8(Config), + setlimit(default), + ex_binaries_errors_utf8(Config), + ex_binaries_errors_utf16_little(Config), + ex_binaries_errors_utf16_big(Config), + ex_binaries_errors_utf32_little(Config), + ex_binaries_errors_utf32_big(Config). + +ex_binaries_errors_utf8(Config) when is_list(Config) -> + %% Original smoke test, we should not forget the original offset... + <<_:8,_:8,RR2/binary>> = <<$a,$b,164,165,$c>>, + {error,[],<<164,165,$c>>} = unicode:characters_to_list(RR2), + %% Now, try with longer binary (trapping) + BrokenPart = list_to_binary(lists:seq(128,255)), + BrokenSz = byte_size(BrokenPart), + [ begin + OKList = lists:flatten(lists:duplicate(N,lists:seq(1,255))), + OKBin = unicode:characters_to_binary(OKList), + OKLen = length(OKList), + %% Copy to avoid that the binary get's writable + PartlyBroken = binary:copy(<>), + PBSz = byte_size(PartlyBroken), + {error,OKList,DeepBrokenPart} = + unicode:characters_to_list(PartlyBroken), + BrokenPart = iolist_to_binary(DeepBrokenPart), + [ begin + NewList = lists:nthtail(X, OKList), + NewSz = byte_size(unicode:characters_to_binary(NewList)) + + BrokenSz, + Chomped = binary:part(PartlyBroken,PBSz - NewSz, NewSz), + true = (binary:referenced_byte_size(Chomped) =:= PBSz), + {error,NewList,DeepBrokenPart2} = + unicode:characters_to_list(Chomped), + BrokenPart = iolist_to_binary(DeepBrokenPart2) + end || X <- lists:seq(1,OKLen) ] + end || N <- lists:seq(1,20) ], + ok. + +ex_binaries_errors_utf16_little(Config) when is_list(Config) -> + BrokenPart = << <> || X <- lists:seq(16#DC00,16#DFFF) >>, + BrokenSz = byte_size(BrokenPart), + [ begin + OKList = lists:flatten(lists:duplicate(N,lists:seq(1,255))), + OKBin = unicode:characters_to_binary(OKList,unicode,{utf16,little}), + OKLen = length(OKList), + %% Copy to avoid that the binary get's writable + PartlyBroken = binary:copy(<>), + PBSz = byte_size(PartlyBroken), + {error,OKList,DeepBrokenPart} = + unicode:characters_to_list(PartlyBroken,{utf16,little}), + BrokenPart = iolist_to_binary(DeepBrokenPart), + [ begin + NewList = lists:nthtail(X, OKList), + NewSz = byte_size(unicode:characters_to_binary(NewList,unicode,{utf16,little})) + + BrokenSz, + Chomped = binary:part(PartlyBroken,PBSz - NewSz, NewSz), + true = (binary:referenced_byte_size(Chomped) =:= PBSz), + {error,NewList,DeepBrokenPart2} = + unicode:characters_to_list(Chomped,{utf16,little}), + BrokenPart = iolist_to_binary(DeepBrokenPart2) + end || X <- lists:seq(1,OKLen) ] + end || N <- lists:seq(1,15) ], + ok. +ex_binaries_errors_utf16_big(Config) when is_list(Config) -> + BrokenPart = << <> || X <- lists:seq(16#DC00,16#DFFF) >>, + BrokenSz = byte_size(BrokenPart), + [ begin + OKList = lists:flatten(lists:duplicate(N,lists:seq(1,255))), + OKBin = unicode:characters_to_binary(OKList,unicode,{utf16,big}), + OKLen = length(OKList), + %% Copy to avoid that the binary get's writable + PartlyBroken = binary:copy(<>), + PBSz = byte_size(PartlyBroken), + {error,OKList,DeepBrokenPart} = + unicode:characters_to_list(PartlyBroken,{utf16,big}), + BrokenPart = iolist_to_binary(DeepBrokenPart), + [ begin + NewList = lists:nthtail(X, OKList), + NewSz = byte_size(unicode:characters_to_binary(NewList,unicode,{utf16,big})) + + BrokenSz, + Chomped = binary:part(PartlyBroken,PBSz - NewSz, NewSz), + true = (binary:referenced_byte_size(Chomped) =:= PBSz), + {error,NewList,DeepBrokenPart2} = + unicode:characters_to_list(Chomped,{utf16,big}), + BrokenPart = iolist_to_binary(DeepBrokenPart2) + end || X <- lists:seq(1,OKLen) ] + end || N <- lists:seq(1,15) ], + ok. + +ex_binaries_errors_utf32_big(Config) when is_list(Config) -> + BrokenPart = << <> || X <- lists:seq(16#DC00,16#DFFF) >>, + BrokenSz = byte_size(BrokenPart), + [ begin + OKList = lists:flatten(lists:duplicate(N,lists:seq(1,255))), + OKBin = unicode:characters_to_binary(OKList,unicode,{utf32,big}), + OKLen = length(OKList), + %% Copy to avoid that the binary get's writable + PartlyBroken = binary:copy(<>), + PBSz = byte_size(PartlyBroken), + {error,OKList,DeepBrokenPart} = + unicode:characters_to_list(PartlyBroken,{utf32,big}), + BrokenPart = iolist_to_binary(DeepBrokenPart), + [ begin + NewList = lists:nthtail(X, OKList), + NewSz = byte_size(unicode:characters_to_binary(NewList,unicode,{utf32,big})) + + BrokenSz, + Chomped = binary:part(PartlyBroken,PBSz - NewSz, NewSz), + true = (binary:referenced_byte_size(Chomped) =:= PBSz), + {error,NewList,DeepBrokenPart2} = + unicode:characters_to_list(Chomped,{utf32,big}), + BrokenPart = iolist_to_binary(DeepBrokenPart2) + end || X <- lists:seq(1,OKLen) ] + end || N <- lists:seq(1,15) ], + ok. + +ex_binaries_errors_utf32_little(Config) when is_list(Config) -> + BrokenPart = << <> || X <- lists:seq(16#DC00,16#DFFF) >>, + BrokenSz = byte_size(BrokenPart), + [ begin + OKList = lists:flatten(lists:duplicate(N,lists:seq(1,255))), + OKBin = unicode:characters_to_binary(OKList,unicode,{utf32,little}), + OKLen = length(OKList), + %% Copy to avoid that the binary get's writable + PartlyBroken = binary:copy(<>), + PBSz = byte_size(PartlyBroken), + {error,OKList,DeepBrokenPart} = + unicode:characters_to_list(PartlyBroken,{utf32,little}), + BrokenPart = iolist_to_binary(DeepBrokenPart), + [ begin + NewList = lists:nthtail(X, OKList), + NewSz = byte_size(unicode:characters_to_binary(NewList,unicode,{utf32,little})) + + BrokenSz, + Chomped = binary:part(PartlyBroken,PBSz - NewSz, NewSz), + true = (binary:referenced_byte_size(Chomped) =:= PBSz), + {error,NewList,DeepBrokenPart2} = + unicode:characters_to_list(Chomped,{utf32,little}), + BrokenPart = iolist_to_binary(DeepBrokenPart2) + end || X <- lists:seq(1,OKLen) ] + end || N <- lists:seq(1,15) ], + ok. + exceptions(Config) when is_list(Config) -> -- cgit v1.2.3 From ab22a60d4e8d7a433789bae44b53305ad0d44cdc Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Thu, 2 May 2013 17:18:22 +0200 Subject: Enable use of GetTickCoun64 when available --- erts/emulator/sys/win32/sys_time.c | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/erts/emulator/sys/win32/sys_time.c b/erts/emulator/sys/win32/sys_time.c index 1a33061ef1..f7f0161b58 100644 --- a/erts/emulator/sys/win32/sys_time.c +++ b/erts/emulator/sys/win32/sys_time.c @@ -79,7 +79,6 @@ static int days_in_month[2][13] = { int sys_init_time(void) { - /* char kernel_dll_name[] = "kernel32"; HMODULE module; @@ -88,7 +87,7 @@ sys_init_time(void) (ULONGLONG (WINAPI *)(void)) GetProcAddress(module,"GetTickCount64") : NULL; - */ + if(GetTimeZoneInformation(&static_tzi) && static_tzi.StandardDate.wMonth != 0 && static_tzi.DaylightDate.wMonth != 0) { @@ -96,13 +95,6 @@ sys_init_time(void) } erts_smp_mtx_init(&wrap_lock, "sys_gethrtime"); - /* - * XXX: Debug - remove me! - */ - if (pGetTickCount64 != NULL) { - fprintf(stderr,"got GetTickCount64!\r\n"); - fflush(stderr); - } return 1; } -- cgit v1.2.3 From 0c1ceeb0a30609a105dd69e000d1c391e2d2927e Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Thu, 2 May 2013 18:49:45 +0200 Subject: Add system_monitor of long_schedule --- erts/doc/src/erlang.xml | 43 +++++++++++++ erts/emulator/beam/atom.names | 4 ++ erts/emulator/beam/beam_emu.c | 22 +++++++ erts/emulator/beam/erl_bif_trace.c | 23 ++++++- erts/emulator/beam/erl_port_task.c | 13 ++++ erts/emulator/beam/erl_process.c | 1 + erts/emulator/beam/erl_process.h | 1 + erts/emulator/beam/erl_trace.c | 128 +++++++++++++++++++++++++++++++++++++ erts/emulator/beam/erl_trace.h | 2 + erts/emulator/beam/global.h | 2 + erts/emulator/beam/utils.c | 18 ++++++ erts/emulator/test/trace_SUITE.erl | 69 ++++++++++++++++++++ erts/preloaded/src/erlang.erl | 1 + lib/test_server/doc/src/notes.xml | 2 - lib/test_server/src/configure.in | 1 + 15 files changed, 326 insertions(+), 4 deletions(-) diff --git a/erts/doc/src/erlang.xml b/erts/doc/src/erlang.xml index 7dc59ea954..20fc9e70f2 100644 --- a/erts/doc/src/erlang.xml +++ b/erts/doc/src/erlang.xml @@ -6058,6 +6058,49 @@ ok notice.

+ {long_schedule, Time} + +

If a process or port in the system runs uninterrupted + for at least Time wall clock milliseconds, a + message {monitor, PidOrPort, long_schedule, Info} + is sent to MonitorPid. PidOrPort is the + process or port that was running and Info is a + list of two-element tuples describing the event. In case + of a pid(), the tuples {timeout, Millis}, + {in, Location} and {out, Location} will be + present, where Location is either an MFA + ({Module, Function, Arity}) describing the + function where the process was scheduled in/out, or the + atom undefined. In case of a port(), the + tuples {timeout, Millis} and {port_op,Op} + will be present. Op will be one of proc_sig, + timeout, input, output, + event or dist_cmd, depending on which + driver callback was executing. proc_sig is an + internal operation and should never appear, while the + others represent the corresponding driver callbacks + timeout, ready_input, ready_output, + event and finally outputv (when the port + is used by distribution). The Millis value in + the timeout tuple will tell you the actual + uninterrupted execution time of the process or port, + which will always be >= the Time value + supplied when starting the trace. New tuples may be + added to the Info lists in the future, and the + order of the tuples in the list may be changed at any + time without prior notice. +

+

This can be used to detect problems with NIF's or + drivers that takes too long to execute. Generally, 1 ms + is considered a good maximum time for a driver callback + or a NIF. However, a time sharing system should usually + consider everything below 100 ms as "possible" and + fairly "normal". Schedule times above that might however + indicate swapping or a NIF/driver that is + misbehaving. Misbehaving NIF's and drivers could cause + bad resource utilization and bad overall performance of + the system.

+ {large_heap, Size}

If a garbage collection in the system results in diff --git a/erts/emulator/beam/atom.names b/erts/emulator/beam/atom.names index ce60bb9bbc..80208d35e1 100644 --- a/erts/emulator/beam/atom.names +++ b/erts/emulator/beam/atom.names @@ -178,6 +178,7 @@ atom disable_trace atom disabled atom display_items atom dist +atom dist_cmd atom Div='/' atom div atom dlink @@ -312,6 +313,7 @@ atom load_cancelled atom load_failure atom local atom long_gc +atom long_schedule atom low atom Lt='<' atom machine @@ -430,6 +432,7 @@ atom port atom ports atom port_count atom port_limit +atom port_op atom print atom priority atom private @@ -441,6 +444,7 @@ atom process_display atom process_limit atom process_dump atom procs +atom proc_sig atom profile atom protected atom protection diff --git a/erts/emulator/beam/beam_emu.c b/erts/emulator/beam/beam_emu.c index 944ed6da81..5781009f58 100644 --- a/erts/emulator/beam/beam_emu.c +++ b/erts/emulator/beam/beam_emu.c @@ -924,6 +924,7 @@ extern int count_instructions; # define NOINLINE #endif + /* * The following functions are called directly by process_main(). * Don't inline them. @@ -1153,6 +1154,9 @@ void process_main(void) Eterm pt_arity; /* Used by do_put_tuple */ + Uint64 start_time = 0; /* Monitor long schedule */ + BeamInstr* start_time_i = NULL; + ERL_BITS_DECLARE_STATEP; /* Has to be last declaration */ @@ -1175,6 +1179,16 @@ void process_main(void) do_schedule: reds_used = REDS_IN(c_p) - FCALLS; do_schedule1: + + if (start_time != 0) { + Sint64 diff = erts_timestamp_millis() - start_time; + if (diff > 0 && (Uint) diff > erts_system_monitor_long_schedule) { + BeamInstr *inptr = find_function_from_pc(start_time_i); + BeamInstr *outptr = find_function_from_pc(c_p->i); + monitor_long_schedule_proc(c_p,inptr,outptr,(Uint) diff); + } + } + PROCESS_MAIN_CHK_LOCKS(c_p); ERTS_SMP_UNREQ_PROC_MAIN_LOCK(c_p); #if HALFWORD_HEAP @@ -1183,11 +1197,18 @@ void process_main(void) ERTS_VERIFY_UNUSED_TEMP_ALLOC(c_p); c_p = schedule(c_p, reds_used); ERTS_VERIFY_UNUSED_TEMP_ALLOC(c_p); + start_time = 0; #ifdef DEBUG pid = c_p->common.id; /* Save for debugging purpouses */ #endif ERTS_SMP_REQ_PROC_MAIN_LOCK(c_p); PROCESS_MAIN_CHK_LOCKS(c_p); + + if (erts_system_monitor_long_schedule != 0) { + start_time = erts_timestamp_millis(); + start_time_i = c_p->i; + } + reg = ERTS_PROC_GET_SCHDATA(c_p)->x_reg_array; freg = ERTS_PROC_GET_SCHDATA(c_p)->f_reg_array; #if !HEAP_ON_C_STACK @@ -6151,6 +6172,7 @@ apply_fun(Process* p, Eterm fun, Eterm args, Eterm* reg) } + static Eterm new_fun(Process* p, Eterm* reg, ErlFunEntry* fe, int num_free) { diff --git a/erts/emulator/beam/erl_bif_trace.c b/erts/emulator/beam/erl_bif_trace.c index 41c98bbffb..14a40dcd7e 100644 --- a/erts/emulator/beam/erl_bif_trace.c +++ b/erts/emulator/beam/erl_bif_trace.c @@ -2014,6 +2014,7 @@ void erts_system_monitor_clear(Process *c_p) { #endif erts_set_system_monitor(NIL); erts_system_monitor_long_gc = 0; + erts_system_monitor_long_schedule = 0; erts_system_monitor_large_heap = 0; erts_system_monitor_flags.busy_port = 0; erts_system_monitor_flags.busy_dist_port = 0; @@ -2038,12 +2039,17 @@ static Eterm system_monitor_get(Process *p) Uint hsz = 3 + (erts_system_monitor_flags.busy_dist_port ? 2 : 0) + (erts_system_monitor_flags.busy_port ? 2 : 0); Eterm long_gc = NIL; + Eterm long_schedule = NIL; Eterm large_heap = NIL; if (erts_system_monitor_long_gc != 0) { hsz += 2+3; (void) erts_bld_uint(NULL, &hsz, erts_system_monitor_long_gc); } + if (erts_system_monitor_long_schedule != 0) { + hsz += 2+3; + (void) erts_bld_uint(NULL, &hsz, erts_system_monitor_long_schedule); + } if (erts_system_monitor_large_heap != 0) { hsz += 2+3; (void) erts_bld_uint(NULL, &hsz, erts_system_monitor_large_heap); @@ -2053,6 +2059,10 @@ static Eterm system_monitor_get(Process *p) if (erts_system_monitor_long_gc != 0) { long_gc = erts_bld_uint(&hp, NULL, erts_system_monitor_long_gc); } + if (erts_system_monitor_long_schedule != 0) { + long_schedule = erts_bld_uint(&hp, NULL, + erts_system_monitor_long_schedule); + } if (erts_system_monitor_large_heap != 0) { large_heap = erts_bld_uint(&hp, NULL, erts_system_monitor_large_heap); } @@ -2061,6 +2071,10 @@ static Eterm system_monitor_get(Process *p) Eterm t = TUPLE2(hp, am_long_gc, long_gc); hp += 3; res = CONS(hp, t, res); hp += 2; } + if (long_schedule != NIL) { + Eterm t = TUPLE2(hp, am_long_schedule, long_schedule); hp += 3; + res = CONS(hp, t, res); hp += 2; + } if (large_heap != NIL) { Eterm t = TUPLE2(hp, am_large_heap, large_heap); hp += 3; res = CONS(hp, t, res); hp += 2; @@ -2115,7 +2129,7 @@ system_monitor(Process *p, Eterm monitor_pid, Eterm list) } if (is_not_list(list)) goto error; else { - Uint long_gc, large_heap; + Uint long_gc, long_schedule, large_heap; int busy_port, busy_dist_port; system_blocked = 1; @@ -2125,7 +2139,8 @@ system_monitor(Process *p, Eterm monitor_pid, Eterm list) if (!erts_pid2proc(p, ERTS_PROC_LOCK_MAIN, monitor_pid, 0)) goto error; - for (long_gc = 0, large_heap = 0, busy_port = 0, busy_dist_port = 0; + for (long_gc = 0, long_schedule = 0, large_heap = 0, + busy_port = 0, busy_dist_port = 0; is_list(list); list = CDR(list_val(list))) { Eterm t = CAR(list_val(list)); @@ -2135,6 +2150,9 @@ system_monitor(Process *p, Eterm monitor_pid, Eterm list) if (tp[1] == am_long_gc) { if (! term_to_Uint(tp[2], &long_gc)) goto error; if (long_gc < 1) long_gc = 1; + } else if (tp[1] == am_long_schedule) { + if (! term_to_Uint(tp[2], &long_schedule)) goto error; + if (long_schedule < 1) long_schedule = 1; } else if (tp[1] == am_large_heap) { if (! term_to_Uint(tp[2], &large_heap)) goto error; if (large_heap < 16384) large_heap = 16384; @@ -2150,6 +2168,7 @@ system_monitor(Process *p, Eterm monitor_pid, Eterm list) prev = system_monitor_get(p); erts_set_system_monitor(monitor_pid); erts_system_monitor_long_gc = long_gc; + erts_system_monitor_long_schedule = long_schedule; erts_system_monitor_large_heap = large_heap; erts_system_monitor_flags.busy_port = !!busy_port; erts_system_monitor_flags.busy_dist_port = !!busy_dist_port; diff --git a/erts/emulator/beam/erl_port_task.c b/erts/emulator/beam/erl_port_task.c index 0ed08bee01..9ba7704106 100644 --- a/erts/emulator/beam/erl_port_task.c +++ b/erts/emulator/beam/erl_port_task.c @@ -1578,6 +1578,7 @@ erts_port_task_execute(ErtsRunQueue *runq, Port **curr_port_pp) int fpe_was_unmasked; erts_aint32_t state; int active; + Uint64 start_time = 0; ERTS_SMP_LC_ASSERT(erts_smp_lc_runq_is_locked(runq)); @@ -1639,6 +1640,10 @@ erts_port_task_execute(ErtsRunQueue *runq, Port **curr_port_pp) reset_handle(ptp); + if (erts_system_monitor_long_schedule != 0) { + start_time = erts_timestamp_millis(); + } + ERTS_SMP_LC_ASSERT(erts_lc_is_port_locked(pp)); ERTS_SMP_CHK_NO_PROC_LOCKS; ASSERT(pp->drv_ptr); @@ -1707,6 +1712,14 @@ erts_port_task_execute(ErtsRunQueue *runq, Port **curr_port_pp) reds += erts_port_driver_callback_epilogue(pp, &state); + if (start_time != 0) { + Sint64 diff = erts_timestamp_millis() - start_time; + if (diff > 0 && (Uint) diff > erts_system_monitor_long_schedule) { + monitor_long_schedule_port(pp,ptp->type,(Uint) diff); + } + } + start_time = 0; + aborted_port_task: schedule_port_task_free(ptp); diff --git a/erts/emulator/beam/erl_process.c b/erts/emulator/beam/erl_process.c index 5d9c5af55f..9618a5555b 100644 --- a/erts/emulator/beam/erl_process.c +++ b/erts/emulator/beam/erl_process.c @@ -267,6 +267,7 @@ static Uint last_exact_reductions; Uint erts_default_process_flags; Eterm erts_system_monitor; Eterm erts_system_monitor_long_gc; +Uint erts_system_monitor_long_schedule; Eterm erts_system_monitor_large_heap; struct erts_system_monitor_flags_t erts_system_monitor_flags; diff --git a/erts/emulator/beam/erl_process.h b/erts/emulator/beam/erl_process.h index 3d3579fa7e..797f9e687b 100644 --- a/erts/emulator/beam/erl_process.h +++ b/erts/emulator/beam/erl_process.h @@ -1002,6 +1002,7 @@ extern erts_smp_rwmtx_t erts_cpu_bind_rwmtx; */ extern Eterm erts_system_monitor; extern Uint erts_system_monitor_long_gc; +extern Uint erts_system_monitor_long_schedule; extern Uint erts_system_monitor_large_heap; struct erts_system_monitor_flags_t { unsigned int busy_port : 1; diff --git a/erts/emulator/beam/erl_trace.c b/erts/emulator/beam/erl_trace.c index 848877d43e..bb6ed44523 100644 --- a/erts/emulator/beam/erl_trace.c +++ b/erts/emulator/beam/erl_trace.c @@ -2268,7 +2268,134 @@ trace_gc(Process *p, Eterm what) #undef LOCAL_HEAP_SIZE } +void +monitor_long_schedule_proc(Process *p, BeamInstr *in_fp, BeamInstr *out_fp, Uint time) +{ + ErlHeapFragment *bp; + ErlOffHeap *off_heap; +#ifndef ERTS_SMP + Process *monitor_p; +#endif + Uint hsz; + Eterm *hp, list, in_mfa = am_undefined, out_mfa = am_undefined; + Eterm in_tpl, out_tpl, tmo_tpl, tmo, msg; + + +#ifndef ERTS_SMP + ASSERT(is_internal_pid(system_monitor)); + monitor_p = erts_proc_lookup(system_monitor); + if (!monitor_p || p == monitor_p) { + return; + } +#endif + /* + * Size: {monitor, pid, long_schedule, [{timeout, T}, {in, {M,F,A}},{out,{M,F,A}}]} -> + * 5 (top tuple of 4), (3 (elements) * 2 (cons)) + 3 (timeout tuple of 2) + size of Timeout + + * (2 * 3 (in/out tuple of 2)) + + * 0 (unknown) or 4 (MFA tuple of 3) + 0 (unknown) or 4 (MFA tuple of 3) + * = 20 + (in_fp != NULL) ? 4 : 0 + (out_fp != NULL) ? 4 : 0 + size of Timeout + */ + hsz = 20 + ((in_fp != NULL) ? 4 : 0) + ((out_fp != NULL) ? 4 : 0); + (void) erts_bld_uint(NULL, &hsz, time); + hp = ERTS_ALLOC_SYSMSG_HEAP(hsz, &bp, &off_heap, monitor_p); + tmo = erts_bld_uint(&hp, NULL, time); + if (in_fp != NULL) { + in_mfa = TUPLE3(hp,(Eterm) in_fp[0], (Eterm) in_fp[1], make_small(in_fp[2])); + hp +=4; + } + if (out_fp != NULL) { + out_mfa = TUPLE3(hp,(Eterm) out_fp[0], (Eterm) out_fp[1], make_small(out_fp[2])); + hp +=4; + } + tmo_tpl = TUPLE2(hp,am_timeout, tmo); + hp += 3; + in_tpl = TUPLE2(hp,am_in,in_mfa); + hp += 3; + out_tpl = TUPLE2(hp,am_out,out_mfa); + hp += 3; + list = CONS(hp,out_tpl,NIL); + hp += 2; + list = CONS(hp,in_tpl,list); + hp += 2; + list = CONS(hp,tmo_tpl,list); + hp += 2; + msg = TUPLE4(hp, am_monitor, p->common.id, am_long_schedule, list); + hp += 5; +#ifdef ERTS_SMP + enqueue_sys_msg(SYS_MSG_TYPE_SYSMON, p->common.id, NIL, msg, bp); +#else + erts_queue_message(monitor_p, NULL, bp, msg, NIL +#ifdef USE_VM_PROBES + , NIL +#endif + ); +#endif +} +void +monitor_long_schedule_port(Port *pp, ErtsPortTaskType type, Uint time) +{ + ErlHeapFragment *bp; + ErlOffHeap *off_heap; +#ifndef ERTS_SMP + Process *monitor_p; +#endif + Uint hsz; + Eterm *hp, list, op; + Eterm op_tpl, tmo_tpl, tmo, msg; + + +#ifndef ERTS_SMP + ASSERT(is_internal_pid(system_monitor)); + monitor_p = erts_proc_lookup(system_monitor); + if (!monitor_p) { + return; + } +#endif + /* + * Size: {monitor, port, long_schedule, [{timeout, T}, {op, Operation}]} -> + * 5 (top tuple of 4), (2 (elements) * 2 (cons)) + 3 (timeout tuple of 2) + * + size of Timeout + 3 (op tuple of 2 atoms) + * = 15 + size of Timeout + */ + hsz = 15; + (void) erts_bld_uint(NULL, &hsz, time); + + hp = ERTS_ALLOC_SYSMSG_HEAP(hsz, &bp, &off_heap, monitor_p); + switch (type) { + case ERTS_PORT_TASK_PROC_SIG: op = am_proc_sig; break; + case ERTS_PORT_TASK_TIMEOUT: op = am_timeout; break; + case ERTS_PORT_TASK_INPUT: op = am_input; break; + case ERTS_PORT_TASK_OUTPUT: op = am_output; break; + case ERTS_PORT_TASK_EVENT: op = am_event; break; + case ERTS_PORT_TASK_DIST_CMD: op = am_dist_cmd; break; + default: op = am_undefined; break; + } + + tmo = erts_bld_uint(&hp, NULL, time); + + op_tpl = TUPLE2(hp,am_port_op,op); + hp += 3; + + tmo_tpl = TUPLE2(hp,am_timeout, tmo); + hp += 3; + + list = CONS(hp,op_tpl,NIL); + hp += 2; + list = CONS(hp,tmo_tpl,list); + hp += 2; + msg = TUPLE4(hp, am_monitor, pp->common.id, am_long_schedule, list); + hp += 5; +#ifdef ERTS_SMP + enqueue_sys_msg(SYS_MSG_TYPE_SYSMON, pp->common.id, NIL, msg, bp); +#else + erts_queue_message(monitor_p, NULL, bp, msg, NIL +#ifdef USE_VM_PROBES + , NIL +#endif + ); +#endif +} void monitor_long_gc(Process *p, Uint time) { @@ -3011,6 +3138,7 @@ sys_msg_disp_failure(ErtsSysMsgQ *smqp, Eterm receiver) case SYS_MSG_TYPE_SYSMON: if (receiver == NIL && !erts_system_monitor_long_gc + && !erts_system_monitor_long_schedule && !erts_system_monitor_large_heap && !erts_system_monitor_flags.busy_port && !erts_system_monitor_flags.busy_dist_port) diff --git a/erts/emulator/beam/erl_trace.h b/erts/emulator/beam/erl_trace.h index 50fb27aab0..54d3aafdda 100644 --- a/erts/emulator/beam/erl_trace.h +++ b/erts/emulator/beam/erl_trace.h @@ -83,6 +83,8 @@ void erts_system_profile_setup_active_schedulers(void); /* system_monitor */ void monitor_long_gc(Process *p, Uint time); +void monitor_long_schedule_proc(Process *p, BeamInstr *in_i, BeamInstr *out_i, Uint time); +void monitor_long_schedule_port(Port *pp, ErtsPortTaskType type, Uint time); void monitor_large_heap(Process *p); void monitor_generic(Process *p, Eterm type, Eterm spec); Uint erts_trace_flag2bit(Eterm flag); diff --git a/erts/emulator/beam/global.h b/erts/emulator/beam/global.h index 012c1c7e6a..12826cf428 100755 --- a/erts/emulator/beam/global.h +++ b/erts/emulator/beam/global.h @@ -746,6 +746,8 @@ void erl_drv_thr_init(void); /* utils.c */ void erts_cleanup_offheap(ErlOffHeap *offheap); +Uint64 erts_timestamp_millis(void); + Export* erts_find_function(Eterm, Eterm, unsigned int, ErtsCodeIndex); Eterm store_external_or_ref_in_proc_(Process *, Eterm); diff --git a/erts/emulator/beam/utils.c b/erts/emulator/beam/utils.c index d5d97d748a..0a833f7e66 100644 --- a/erts/emulator/beam/utils.c +++ b/erts/emulator/beam/utils.c @@ -3722,6 +3722,24 @@ erts_smp_ensure_later_interval_acqb(erts_interval_t *icp, Uint64 ic) } +/* + * A millisecond timestamp without time correction where there's no hrtime + * - for tracing on "long" things... + */ +Uint64 erts_timestamp_millis(void) +{ +#ifdef HAVE_GETHRTIME + return (Uint64) (sys_gethrtime() / 1000000); +#else + Uint64 res; + SysTimeval tv; + sys_gettimeofday(&tv); + res = (Uint64) tv.tv_sec*1000000; + res += (Uint64) tv.tv_usec; + return (res / 1000); +#endif +} + #ifdef DEBUG /* * Handy functions when using a debugger - don't use in the code! diff --git a/erts/emulator/test/trace_SUITE.erl b/erts/emulator/test/trace_SUITE.erl index 221b65309a..caa58ae281 100644 --- a/erts/emulator/test/trace_SUITE.erl +++ b/erts/emulator/test/trace_SUITE.erl @@ -34,6 +34,7 @@ system_monitor_args/1, more_system_monitor_args/1, system_monitor_long_gc_1/1, system_monitor_long_gc_2/1, system_monitor_large_heap_1/1, system_monitor_large_heap_2/1, + system_monitor_long_schedule/1, bad_flag/1, trace_delivered/1]). -include_lib("test_server/include/test_server.hrl"). @@ -52,6 +53,7 @@ all() -> set_on_first_spawn, system_monitor_args, more_system_monitor_args, system_monitor_long_gc_1, system_monitor_long_gc_2, system_monitor_large_heap_1, + system_monitor_long_schedule, system_monitor_large_heap_2, bad_flag, trace_delivered]. groups() -> @@ -508,6 +510,65 @@ try_l(Val) -> ?line {Self,Comb1} = erlang:system_monitor(undefined), ?line [{large_heap,Val},{long_gc,Arbitrary2}] = lists:sort(Comb1). +monitor_sys(Parent) -> + receive + {monitor,Pid,long_schedule,Data} when is_pid(Pid) -> + io:format("Long schedule of ~w: ~w~n",[Pid,Data]), + Parent ! {Pid,Data}, + monitor_sys(Parent); + {monitor,Port,long_schedule,Data} when is_port(Port) -> + {name,Name} = erlang:port_info(Port,name), + io:format("Long schedule of ~w (~p): ~w~n",[Port,Name,Data]), + Parent ! {Port,Data}, + monitor_sys(Parent); + Other -> + erlang:display(Other) + end. + +start_monitor() -> + Parent = self(), + Mpid = spawn_link(fun() -> monitor_sys(Parent) end), + erlang:system_monitor(Mpid,[{long_schedule,100}]), + erlang:yield(), % Need to be rescheduled for the trace to take + ok. + +system_monitor_long_schedule(suite) -> + []; +system_monitor_long_schedule(doc) -> + ["Tests erlang:system_monitor(Pid, [{long_schedule,Time}])"]; +system_monitor_long_schedule(Config) when is_list(Config) -> + Path = ?config(data_dir, Config), + erl_ddll:start(), + case (catch load_driver(Path, slow_drv)) of + ok -> + do_system_monitor_long_schedule(); + _Error -> + {skip, "Unable to load slow_drv (windows or no usleep()?)"} + end. +do_system_monitor_long_schedule() -> + start_monitor(), + Port = open_port({spawn_driver,slow_drv}, []), + "ok" = erlang:port_control(Port,0,[]), + Self = self(), + receive + {Self,L} when is_list(L) -> + ok + after 1000 -> + ?t:fail(no_trace_of_pid) + end, + "ok" = erlang:port_control(Port,1,[]), + "ok" = erlang:port_control(Port,2,[]), + receive + {Port,LL} when is_list(LL) -> + ok + after 1000 -> + ?t:fail(no_trace_of_port) + end, + port_close(Port), + erlang:system_monitor(undefined), + ok. + + -define(LONG_GC_SLEEP, 670). system_monitor_long_gc_1(suite) -> @@ -1521,3 +1582,11 @@ issue_non_empty_runq_warning(DeadLine, RQLen) -> " Processes info: ~p~n", [DeadLine div 1000, RQLen, self(), PIs]), receive after 1000 -> ok end. + +load_driver(Dir, Driver) -> + case erl_ddll:load_driver(Dir, Driver) of + ok -> ok; + {error, Error} = Res -> + io:format("~s\n", [erl_ddll:format_error(Error)]), + Res + end. diff --git a/erts/preloaded/src/erlang.erl b/erts/preloaded/src/erlang.erl index fefe0f21e0..647da77881 100644 --- a/erts/preloaded/src/erlang.erl +++ b/erts/preloaded/src/erlang.erl @@ -187,6 +187,7 @@ 'busy_port' | 'busy_dist_port' | {'long_gc', non_neg_integer()} | + {'long_schedule', non_neg_integer()} | {'large_heap', non_neg_integer()}. diff --git a/lib/test_server/doc/src/notes.xml b/lib/test_server/doc/src/notes.xml index b35929f1e6..0eab939a46 100644 --- a/lib/test_server/doc/src/notes.xml +++ b/lib/test_server/doc/src/notes.xml @@ -226,8 +226,6 @@ unicode:characters_to_binary for conversion between binaries and strings instead of binary_to_list and list_to_binary.

-

- Own Id: OTP-10783

 diff --git a/lib/test_server/src/configure.in b/lib/test_server/src/configure.in index 785bab395c..b8fddf1481 100644 --- a/lib/test_server/src/configure.in +++ b/lib/test_server/src/configure.in @@ -276,6 +276,7 @@ AC_CHECK_FUNC(gethostbyname, , AC_CHECK_LIB(nsl, main, [LIBS="$LIBS -lnsl"])) dnl Checks for library functions. AC_CHECK_FUNCS(strerror) AC_CHECK_FUNCS(vsnprintf) +AC_CHECK_FUNCS(usleep) # First check if the library is available, then if we can choose between # two versions of gethostbyname -- cgit v1.2.3 From eb4d4c133a8c2ad00807888289cb99d67f70896f Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Mon, 6 May 2013 14:53:07 +0200 Subject: Minor spelling correction --- erts/doc/src/erlang.xml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/erts/doc/src/erlang.xml b/erts/doc/src/erlang.xml index 20fc9e70f2..767edc1cc0 100644 --- a/erts/doc/src/erlang.xml +++ b/erts/doc/src/erlang.xml @@ -6086,12 +6086,12 @@ ok uninterrupted execution time of the process or port, which will always be >= the Time value supplied when starting the trace. New tuples may be - added to the Info lists in the future, and the + added to the Info list in the future, and the order of the tuples in the list may be changed at any time without prior notice.

This can be used to detect problems with NIF's or - drivers that takes too long to execute. Generally, 1 ms + drivers that take too long to execute. Generally, 1 ms is considered a good maximum time for a driver callback or a NIF. However, a time sharing system should usually consider everything below 100 ms as "possible" and -- cgit v1.2.3 From edd8cb0a3e86c4ee23e4aa4ffa330607923590a0 Mon Sep 17 00:00:00 2001 From: Patrik Nyblom Date: Mon, 6 May 2013 15:25:20 +0200 Subject: Raise the minimal supported Windows version From previous 0x0500 to 0x0501, which obsoletes W2k. This is needed for full IPV6 support. --- erts/configure.in | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/erts/configure.in b/erts/configure.in index 2ee907b6e4..2ae8e90d3f 100644 --- a/erts/configure.in +++ b/erts/configure.in @@ -429,7 +429,7 @@ case $host_os in win32) # The ethread library requires _WIN32_WINNT of at least 0x0403. # -D_WIN32_WINNT=* from CPPFLAGS is saved in ETHR_DEFS. - CPPFLAGS="$CPPFLAGS -D_WIN32_WINNT=0x0500 -DWINVER=0x0500" + CPPFLAGS="$CPPFLAGS -D_WIN32_WINNT=0x0501 -DWINVER=0x0501" ;; darwin*) CPPFLAGS="$CPPFLAGS -D_XOPEN_SOURCE" -- cgit v1.2.3