Code which demonstrates a process getting starved in R15 and earlier

schedule.erl

%% Throwaway to investigate how long gzipping a logfile freezes out
%% other processes.
%%
%% Typical run
%% -----------
%%
%%   /usr/local/src/otp_src_R14B03/bin/erl -smp disable -s schedule go -s init stop
%% This leaves a logfile, 'erlang_timestamps.txt' which shows that the
%% 'sleeper()' process doesn't get any CPU time for about 700 milliseconds.
%% Ideally, sleeper() gets CPU every 10 ms or so.
%%
%% Ways to make the problem go away
%% --------------------------------
%%
%% - Run R16 or newer. Complete fix.
%% - Leave smp enabled. Complete fix, but the real target is single-core.
%% - Reduce the size of the logfile chunk (currently 500 k)
%% - Add a call to erlang:yield() in step(). Reduces freezing to 100ms.
%% - Add a call to timer:sleep(1) in step(). Reduces freezing to 45ms.
%%
-module(schedule).
-export([go/0, go/1]).

go(_) -> go().

go() ->
    os:cmd("dd if=/dev/random bs=1000 count=3600 | hexdump > logfile.txt"),
    Parent = self(),
    Pid = spawn_link(fun() -> Parent ! sleeper([]) end),
    timer:sleep(60),
    Compress_times = compress_log(),
    timer:sleep(60),
    Pid ! stop,

    {ok, F} = file:open("erlang_timestamps.txt", [write]),
    receive
        R_sleep_times ->
            Sleep_times = lists:reverse(R_sleep_times),
            First = hd(Sleep_times),
            io:fwrite(F, "~w ------------------- Time zero, compress is ~w sleeper is ~w\n",
                      [microsecs(First), Parent, Pid]),
            analyse_times(F, First, Sleep_times, Compress_times)
    end,
    file:close(F).

sleeper(Times) ->
    receive
        stop -> Times
    after 10 ->
            sleeper([now()|Times])
    end.

compress_log() ->
    {ok, Out} = file:open("logfile.txt.gz", [write, raw, binary, compressed]),
    {ok, In}  = file:open("logfile.txt", [read, raw, binary]),

    Times = [ step(In, Out) || _ <- lists:seq(1,20) ],

    ok = file:close(In),
    ok = file:close(Out),
    Times.

step(In, Out) ->
    {ok, Bin} = file:read(In, 500000),
    ok = file:write(Out, Bin),
    now().

analyse_times(_, _, [], []) ->
    done;

analyse_times(F, Start, [SH|ST], C) when C == []; SH < hd(C) ->
    Diff = timer:now_diff(SH, Start),
    io:fwrite(F, "~w sleeping. relative ~w\n", [microsecs(SH), Diff div 1000]),
    analyse_times(F, Start, ST, C);

analyse_times(F, Start, S, [CH|CT]) ->
    Diff = timer:now_diff(CH, Start),
    io:fwrite(F, "~w compressing. relative ~w ms\n", [microsecs(CH), Diff div 1000]),
    analyse_times(F, Start, S, CT).

microsecs({_, Secs, Microsecs}) ->
    (Secs * 1000000 + Microsecs) rem 16#ffffFFFF.