Clean up debug logs

apps/arweave/src/ar_http.erl

@@ -139,14 +139,12 @@ handle_cast(Cast, State) ->
  ?LOG_WARNING([{event, unhandled_cast}, {module, ?MODULE}, {cast, Cast}]),
  {noreply, State}.
 
-handle_info({gun_up, PID, Protocol}, #state{ status_by_pid = StatusByPID } = State) ->
+handle_info({gun_up, PID, _Protocol}, #state{ status_by_pid = StatusByPID } = State) ->
  case maps:get(PID, StatusByPID, not_found) of
  not_found ->
  %% A connection timeout should have occurred.
  {noreply, State};
  {{connecting, PendingRequests}, MonitorRef, Peer} ->
- ?LOG_DEBUG([{event, established_connection}, {protocol, Protocol},
- {peer, ar_util:format_peer(Peer)}]),
  [gen_server:reply(ReplyTo, {ok, PID}) || {ReplyTo, _} <- PendingRequests],
  StatusByPID2 = maps:put(PID, {connected, MonitorRef, Peer}, StatusByPID),
  prometheus_gauge:inc(outbound_connections),
@@ -211,21 +209,15 @@ handle_info({gun_down, PID, Protocol, Reason, _KilledStreams, _UnprocessedStream
  prometheus_gauge:dec(outbound_connections),
  ok
  end,
- ?LOG_DEBUG([{event, connection_down}, {protocol, Protocol},
- {reason, io_lib:format("~p", [Reason])}]),
  {noreply, State#state{ status_by_pid = StatusByPID2, pid_by_peer = PIDByPeer2 }}
  end;
 
 handle_info({'DOWN', _Ref, process, PID, Reason},
  #state{ pid_by_peer = PIDByPeer, status_by_pid = StatusByPID } = State) ->
  case maps:get(PID, StatusByPID, not_found) of
  not_found ->
- ?LOG_DEBUG([{event, gun_connection_process_down}, {pid, PID}, {peer, unknown},
- {reason, io_lib:format("~p", [Reason])}]),
  {noreply, State};
  {Status, _MonitorRef, Peer} ->
- ?LOG_DEBUG([{event, gun_connection_process_down}, {pid, PID},
- {peer, ar_util:format_peer(Peer)}, {reason, io_lib:format("~p", [Reason])}]),
  PIDByPeer2 = maps:remove(Peer, PIDByPeer),
  StatusByPID2 = maps:remove(PID, StatusByPID),
  case Status of

apps/arweave/src/ar_metrics.erl

@@ -441,6 +441,9 @@ register() ->
  "'type' can be 'sync_range' or 'read_range'. 'peer' is the peer the task "
  "is intended for - for 'read_range' tasks this will be 'localhost'."}]),
 
+ %% --------------------------------------------------------------------------------------------
+ %% Debug-only metrics
+ %% --------------------------------------------------------------------------------------------
  prometheus_counter:new([{name, process_functions},
  {labels, [process]},
  {help, "Sampling active functions. The 'process' label is a fully qualified "
@@ -454,7 +457,10 @@ register() ->
  {labels, [type]},
  {help, "Average scheduler utilization. `type` maps to the sched_type as defined here: "
  "https://www.erlang.org/doc/man/scheduler#type-sched_util_result. "
- "Only set when debug=true."}]).
+ "Only set when debug=true."}]),
+ prometheus_gauge:new([{name, allocator},
+ {labels, [type, instance, section, metric]},
+ {help, "Erlang VM memory allocator metrics. Only set when debug=true."}]).
 
 
 %% @doc Return the HTTP status class label for cowboy_requests_total and gun_requests_total

apps/arweave/src/ar_mining_hash.erl

@@ -13,8 +13,6 @@
 -include_lib("arweave/include/ar_mining.hrl").
 -include_lib("eunit/include/eunit.hrl").
 
--define(SAMPLE_PROCESS_INTERVAL, 1000).
-
 -record(state, {
  hashing_threads = queue:new(),
  hashing_thread_monitor_refs = #{},
@@ -57,7 +55,6 @@ init([]) ->
  #state{},
  lists:seq(1, Config#config.hashing_threads)
  ),
- % ar_util:cast_after(?SAMPLE_PROCESS_INTERVAL, ?MODULE, sample_process),
  {ok, State}.
 
 handle_call(Request, _From, State) ->
@@ -67,22 +64,6 @@ handle_call(Request, _From, State) ->
 handle_cast({set_cache_limit, CacheLimit}, State) ->
  {noreply, State#state{ chunk_cache_limit = CacheLimit }};
 
-handle_cast(sample_process, State) ->
- [{binary, BinInfoBefore}] = process_info(self(), [binary]),
- ?LOG_DEBUG([{event, mining_hash_process_sample},{pid, self()}, {b, length(BinInfoBefore)},
- {binary_before, BinInfoBefore}]),
- queue:fold(
- fun(Thread, _) ->
- [{binary, BinInfoBefore2}] = process_info(Thread, [binary]),
- ?LOG_DEBUG([{event, mining_hash_thread_sample}, {thread, Thread}, {b, length(BinInfoBefore2)},
- {binary_before, BinInfoBefore2}])
- end,
- ok,
- State#state.hashing_threads
- ),
- ar_util:cast_after(?SAMPLE_PROCESS_INTERVAL, ?MODULE, sample_process),
- {noreply, State};
-
 handle_cast({compute, HashType, Worker, Candidate},
  #state{ hashing_threads = Threads } = State) ->
  {Thread, Threads2} = pick_hashing_thread(Threads),
@@ -157,7 +138,6 @@ handle_hashing_thread_down(Ref, Reason,
  start_hashing_thread(State#state{ hashing_threads = Threads2,
  hashing_thread_monitor_refs = Refs2 }).
 
-
 hashing_thread() ->
  receive
  {compute, h0, Worker, Candidate} ->

apps/arweave/src/ar_mining_io.erl

@@ -13,8 +13,6 @@
 -include_lib("arweave/include/ar_mining.hrl").
 -include_lib("eunit/include/eunit.hrl").
 
--define(SAMPLE_PROCESS_INTERVAL, 1000).
-
 -record(state, {
  partition_upper_bound = 0,
  io_threads = #{},
@@ -74,7 +72,6 @@ init([]) ->
  #state{},
  get_io_channels()
  ),
- % ar_util:cast_after(?SAMPLE_PROCESS_INTERVAL, ?MODULE, sample_process),
  {ok, State}.
 
 handle_call({set_largest_seen_upper_bound, PartitionUpperBound}, _From, State) ->
@@ -107,32 +104,6 @@ handle_call(Request, _From, State) ->
  ?LOG_WARNING([{event, unhandled_call}, {module, ?MODULE}, {request, Request}]),
  {reply, ok, State}.
 
-handle_cast(sample_process, State) ->
- [{binary, BinInfoBefore}] = process_info(self(), [binary]),
- ?LOG_DEBUG([{event, mining_io_process_sample},{pid, self()}, {b, length(BinInfoBefore)},
- {binary_before, BinInfoBefore}]),
- % [{binary, BinInfoBefore}] = process_info(self(), [binary]),
- % garbage_collect(self()),
- % [{binary, BinInfoAfter}] = process_info(self(), [binary]),
- % ?LOG_DEBUG([{event, mining_io_process_sample},{pid, self()}, {b, length(BinInfoBefore)},
- % {a, length(BinInfoAfter)}, {binary_before, BinInfoBefore}, {binary_after, BinInfoAfter}]),
- maps:fold(
- fun(_Key, Thread, _) ->
- [{binary, BinInfoBefore2}] = process_info(Thread, [binary]),
- ?LOG_DEBUG([{event, mining_io_thread_sample}, {thread, Thread}, {b, length(BinInfoBefore2)},
- {binary_before, BinInfoBefore2}])
- % [{binary, BinInfoBefore2}] = process_info(Thread, [binary]),
- % garbage_collect(self()),
- % [{binary, BinInfoAfter2}] = process_info(Thread, [binary]),
- % ?LOG_DEBUG([{event, mining_io_thread_sample}, {thread, Thread}, {b, length(BinInfoBefore2)},
- % {a, length(BinInfoAfter2)}, {binary_before, BinInfoBefore2}, {binary_after, BinInfoAfter2}])
- end,
- ok,
- State#state.io_threads
- ),
- ar_util:cast_after(?SAMPLE_PROCESS_INTERVAL, ?MODULE, sample_process),
- {noreply, State};
-
 handle_cast(garbage_collect, State) ->
  erlang:garbage_collect(self(),
  [{async, {ar_mining_io, self(), erlang:monotonic_time()}}]),

apps/arweave/src/ar_mining_worker.erl

@@ -115,25 +115,12 @@ init(Partition) ->
  gen_server:cast(self(), handle_task),
  gen_server:cast(self(), maybe_warn_about_lag),
  prometheus_gauge:set(mining_server_chunk_cache_size, [Partition], 0),
- % ar_util:cast_after(?SAMPLE_PROCESS_INTERVAL, self(), sample_process),
  {ok, #state{ name = Name, partition_number = Partition }}.
 
 handle_call(Request, _From, State) ->
  ?LOG_WARNING([{event, unhandled_call}, {module, ?MODULE}, {request, Request}]),
  {reply, ok, State}.
 
-handle_cast(sample_process, State) ->
- [{binary, BinInfoBefore}] = process_info(self(), [binary]),
- ?LOG_DEBUG([{event, mining_worker_process_sample}, {worker, State#state.name}, {pid, self()}, {b, length(BinInfoBefore)},
- {binary_before, BinInfoBefore}]),
- % [{binary, BinInfoBefore}] = process_info(self(), [binary]),
- % garbage_collect(self()),
- % [{binary, BinInfoAfter}] = process_info(self(), [binary]),
- % ?LOG_DEBUG([{event, mining_worker_process_sample}, {worker, State#state.name}, {pid, self()}, {b, length(BinInfoBefore)},
- % {a, length(BinInfoAfter)}, {binary_before, BinInfoBefore}, {binary_after, BinInfoAfter}]),
- ar_util:cast_after(?SAMPLE_PROCESS_INTERVAL, self(), sample_process),
- {noreply, State};
-
 handle_cast({set_difficulty, Diff}, State) ->
  {noreply, State#state{ diff = Diff }};
 

apps/arweave/src/ar_process_sampler.erl

@@ -6,7 +6,7 @@
 -export([start_link/0]).
 -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2]).
 
--define(SAMPLE_PROCESSES_INTERVAL, 10000).
+-define(SAMPLE_PROCESSES_INTERVAL, 15000).
 -define(SAMPLE_SCHEDULERS_INTERVAL, 30000).
 -define(SAMPLE_SCHEDULERS_DURATION, 5000).
 
@@ -80,15 +80,11 @@ handle_info(sample_processes, State) ->
  prometheus_gauge:set(process_info, [code, memory], erlang:memory(code)),
  prometheus_gauge:set(process_info, [ets, memory], erlang:memory(ets)),
 
+ log_binary_alloc(),
+
  EndTime = erlang:monotonic_time(),
  ElapsedTime = erlang:convert_time_unit(EndTime-StartTime, native, microsecond),
  ?LOG_DEBUG([{event, sample_processes}, {elapsed_ms, ElapsedTime / 1000}]),
- BinaryAllocator = io_lib:format("~p\n",[erlang:system_info({allocator,binary_alloc})]),
- MsegAllocator = io_lib:format("~p\n",[erlang:system_info({allocator,mseg_alloc})]),
- SysAllocator = io_lib:format("~p\n",[erlang:system_info({allocator,sys_alloc})]),
- ?LOG_DEBUG([{event, binary_allocator}, {binary_allocator, BinaryAllocator}]),
- ?LOG_DEBUG([{event, mseg_allocator}, {mseg_allocator, MsegAllocator}]),
- ?LOG_DEBUG([{event, sys_allocator}, {sys_allocator, SysAllocator}]),
  {noreply, State};
 
 handle_info(_Info, State) ->
@@ -152,15 +148,65 @@ process_function(Pid) ->
  false
  end.
 
-binary_memory([{ID, Size, _RefCount} | BinInfo], IDs, Total) ->
- case sets:is_element(ID, IDs) of
- true ->
- binary_memory(BinInfo, IDs, Total);
- false ->
- binary_memory(BinInfo, sets:add_element(ID, IDs), Total + Size)
- end;
-binary_memory([], _IDs, Total) ->
- Total.
+log_binary_alloc() ->
+ [Instance0 | _Rest] = erlang:system_info({allocator, binary_alloc}),
+ log_binary_alloc_instances([Instance0]).
+
+log_binary_alloc_instances([]) ->
+ ok;
+log_binary_alloc_instances([Instance | _Rest]) ->
+ {instance, Id, [
+ _Versions,
+ _Options,
+ MBCS,
+ SBCS,
+ Calls
+ ]} = Instance,
+ {calls, [
+ {binary_alloc, AllocGigaCount, AllocCount},
+ {binary_free, FreeGigaCount, FreeCount},
+ {binary_realloc, ReallocGigaCount, ReallocCount},
+ _MsegAllocCount, _MsegDeallocCount, _MsegReallocCount,
+ _SysAllocCount, _SysDeallocCount, _SysReallocCount
+ ]} = Calls,
+
+ log_binary_alloc_carrier(Id, MBCS),
+ log_binary_alloc_carrier(Id, SBCS),
+
+ prometheus_gauge:set(allocator, [binary, Id, calls, binary_alloc_count],
+ (AllocGigaCount * 1000000000) + AllocCount),
+ prometheus_gauge:set(allocator, [binary, Id, calls, binary_free_count],
+ (FreeGigaCount * 1000000000) + FreeCount),
+ prometheus_gauge:set(allocator, [binary, Id, calls, binary_realloc_count],
+ (ReallocGigaCount * 1000000000) + ReallocCount).
+
+log_binary_alloc_carrier(Id, Carrier) ->
+ {CarrierType, [
+ {blocks, Blocks},
+ {carriers, _, CarrierCount, _},
+ _MsegCount, _SysCount,
+ {carriers_size, _, CarrierSize, _},
+ _MsegSize, _SysSize
+ ]} = Carrier,
+
+ case Blocks of
+ [{binary_alloc, [{count, _, BlockCount, _}, {size, _, BlockSize, _}]}] ->
+ prometheus_gauge:set(allocator, [binary, Id, CarrierType, binary_block_count],
+ BlockCount),
+ prometheus_gauge:set(allocator, [binary, Id, CarrierType, binary_block_size],
+ BlockSize);
+ _ ->
+ prometheus_gauge:set(allocator, [binary, Id, CarrierType, binary_block_count],
+ 0),
+ prometheus_gauge:set(allocator, [binary, Id, CarrierType, binary_block_size],
+ 0)
+ end,
+
+ prometheus_gauge:set(allocator, [binary, Id, CarrierType, binary_carrier_count],
+ CarrierCount),
+ prometheus_gauge:set(allocator, [binary, Id, CarrierType, binary_carrier_size], 
+ CarrierSize).
+
 
 %% @doc Anonymous processes don't have a registered name. So we'll name them after their
 %% module, function and arity.
@@ -181,7 +227,3 @@ initial_call([{proc_lib, init_p_do_apply, _A, _Location} | Stack]) ->
  initial_call(Stack);
 initial_call([InitialCall | _Stack]) ->
  InitialCall.
-
-
-function_name(ProcessName, {M, F, A}) ->
- ProcessName ++ "~" ++ atom_to_list(M) ++ ":" ++ atom_to_list(F) ++ "/" ++ integer_to_list(A).