Merge branch 'bmk/snmp/20201030/mib_server_cache_improvements/OTP-16989' into maint-22

* bmk/snmp/20201030/mib_server_cache_improvements/OTP-16989:
  [snmp|agent|doc] Updated the mib-server option gclimit entry
  [snmp|agent|test] Adjust mibs:cache test case
  [snmp|agent] Adjust the mib server cache gc

4 files changed, 435 insertions, 110 deletions

diff --git a/lib/snmp/doc/src/snmp_app.xml b/lib/snmp/doc/src/snmp_app.xml
index 978aff59b1..b080301143 100644
--- a/lib/snmp/doc/src/snmp_app.xml
+++ b/lib/snmp/doc/src/snmp_app.xml
@@ -526,14 +526,20 @@ in the snmp_config file!
       </item>
 
       <tag><marker id="agent_ms_cache_gclimit"></marker>
-        <c><![CDATA[mibs_cache_gclimit() = integer() > 0 | infinity <optional>]]></c></tag>
+        <c><![CDATA[mibs_cache_gclimit() = infinity | integer() > 0 <optional>]]></c></tag>
       <item>
         <p>When performing a GC, this is the max number of cache entries 
 	that will be deleted from the cache. </p>
-        <p>The reason for having this limit is that if the cache is 
+
+	<p>The reason why its possible to set a limit, is that if the cache is 
 	large, the GC can potentially take a long time, during which 
-	the agent is locked. </p>
-	<p>Default is <c>100</c>.</p>
+	the agent is "busy".
+	<em>But</em> on a heavily loaded system, we also risk not removing
+	enough elements in the cache, instead causing it to grow over time.
+	This is the reason the default value is <c>infinity</c>, which will
+	ensure that <em>all</em> candidates are removed as soon as possible. </p>
+
+	<p>Default is <c>infinity</c>.</p>
       </item>
 
       <tag><marker id="agent_error_report_mod"></marker>
diff --git a/lib/snmp/doc/src/snmp_config.xml b/lib/snmp/doc/src/snmp_config.xml
index 79c6703c94..8ced577a8a 100644
--- a/lib/snmp/doc/src/snmp_config.xml
+++ b/lib/snmp/doc/src/snmp_config.xml
@@ -544,14 +544,19 @@ in so far as it will be converted to the new format if found.
       </item>
 
       <tag><marker id="agent_ms_cache_gclimit"></marker>
-        <c><![CDATA[mibs_cache_gclimit() = integer() > 0 | infinity <optional>]]></c></tag>
+        <c><![CDATA[mibs_cache_gclimit() = infinity | integer() > 0 <optional>]]></c></tag>
       <item>
         <p>When performing a GC, this is the max number of cache entries 
 	that will be deleted from the cache. </p>
-	<p>The reason for having this limit is that if the cache is 
+
+	<p>The reason why its possible to set a limit, is that if the cache is 
 	large, the GC can potentially take a long time, during which 
-	the agent is locked. </p>
-	<p>Default is <c>100</c>.</p>
+	the agent is "busy".
+	<em>But</em> on a heavily loaded system, we also risk not removing
+	enough elements in the cache, instead causing it to grow over time.
+	This is the reason the default value is <c>infinity</c>, which will
+	ensure that <em>all</em> candidates are removed as soon as possible. </p>
+	<p>Default is <c>infinity</c>.</p>
       </item>
 
       <tag><marker id="agent_error_report_mod"></marker>
diff --git a/lib/snmp/src/agent/snmpa_mib.erl b/lib/snmp/src/agent/snmpa_mib.erl
index ab1098514c..8e594213f9 100644
--- a/lib/snmp/src/agent/snmpa_mib.erl
+++ b/lib/snmp/src/agent/snmpa_mib.erl
@@ -40,14 +40,18 @@
 	 which_cache_size/1
 	]).
 
-%% <BACKWARD-COMPAT>
--export([load_mibs/2, unload_mibs/2]).
-%% </BACKWARD-COMPAT>
+%% Utility exports
+-export([subscribe_gc_events/1, unsubscribe_gc_events/1]).
 
 %% Internal exports
 -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
 	 code_change/3]).
 
+%% <BACKWARD-COMPAT>
+-export([load_mibs/2, unload_mibs/2]).
+%% </BACKWARD-COMPAT>
+
+
 -include_lib("kernel/include/file.hrl").
 -include("snmpa_internal.hrl").
 -include("snmp_types.hrl").
@@ -55,14 +59,15 @@
 -include("snmp_debug.hrl").
 
 
--define(SERVER,                ?MODULE).
--define(NO_CACHE,              no_mibs_cache).
--define(DEFAULT_CACHE_USAGE,   true).
--define(CACHE_GC_TICKTIME,     timer:minutes(1)).
--define(DEFAULT_CACHE_AUTOGC,  true).
--define(DEFAULT_CACHE_GCLIMIT, 100).
--define(DEFAULT_CACHE_AGE,     timer:minutes(10)).
--define(CACHE_GC_TRIGGER,      cache_gc_trigger).
+-define(SERVER,                  ?MODULE).
+-define(NO_CACHE,                no_mibs_cache).
+-define(DEFAULT_CACHE_USAGE,     true).
+-define(CACHE_GC_TICKTIME,       timer:minutes(1)).
+-define(DEFAULT_CACHE_AUTOGC,    true).
+-define(DEFAULT_CACHE_GCLIMIT,   infinity). % 100).
+-define(DEFAULT_CACHE_GCVERBOSE, false).
+-define(DEFAULT_CACHE_AGE,       timer:minutes(10)).
+-define(CACHE_GC_TRIGGER,        cache_gc_trigger).
 
 
 
@@ -85,7 +90,8 @@
 %%-----------------------------------------------------------------
 -record(state, 
 	{data, meo, teo, backup, 
-	 cache, cache_tmr, cache_autogc, cache_gclimit, cache_age, 
+	 cache, cache_tmr, cache_autogc, cache_gclimit, cache_age,
+         cache_sub, cache_gcverbose = false,
 	 data_mod}).
 
 
@@ -153,6 +159,13 @@ update_cache_opts(MibServer, Key, Value) ->
     call(MibServer, {update_cache_opts, Key, Value}).
 
 
+subscribe_gc_events(MibServer) ->
+    call(MibServer, {subscribe_gc_events, self()}).
+
+unsubscribe_gc_events(MibServer) ->
+    call(MibServer, {unsubscribe_gc_events, self()}).
+
+
 %%-----------------------------------------------------------------
 %% Func: lookup/2
 %% Purpose: Finds the mib entry corresponding to the Oid. If it is a
@@ -277,7 +290,7 @@ do_init(Prio, Mibs, Opts) ->
     process_flag(trap_exit, true),
     put(sname, ms),
     put(verbosity, ?vvalidate(get_verbosity(Opts))),
-    ?vlog("starting",[]),
+    ?vlog("starting", []),
 
     %% Extract the cache options
     {Cache, CacheOptions} = 
@@ -291,9 +304,10 @@ do_init(Prio, Mibs, Opts) ->
 	    Bad ->
 		throw({error, {bad_option, {cache, Bad}}})
 	end,
-    CacheAutoGC  = get_cacheopt_autogc(Cache,  CacheOptions), 
-    CacheGcLimit = get_cacheopt_gclimit(Cache, CacheOptions), 
-    CacheAge     = get_cacheopt_age(Cache,     CacheOptions), 
+    CacheAutoGC  = get_cacheopt_autogc(Cache,    CacheOptions), 
+    CacheGcLimit = get_cacheopt_gclimit(Cache,   CacheOptions), 
+    CacheAge     = get_cacheopt_age(Cache,       CacheOptions), 
+    CacheGcVerb  = get_cacheopt_gcverbose(Cache, CacheOptions), 
     
     %% Maybe start the cache gc timer
     CacheGcTimer = 
@@ -322,15 +336,16 @@ do_init(Prio, Mibs, Opts) ->
 	    ?vdebug("started",[]),
 	    MibDataMod:sync(Data2),
 	    ?vdebug("mib data synced",[]),
-	    {ok, #state{data          = Data2, 
-			teo           = TeOverride, 
-			meo           = MeOverride,
-			cache         = Cache, 
-			cache_tmr     = CacheGcTimer, 
-			cache_autogc  = CacheAutoGC,
-			cache_gclimit = CacheGcLimit,
-			cache_age     = CacheAge, 
-			data_mod      = MibDataMod}};
+	    {ok, #state{data            = Data2, 
+			teo             = TeOverride, 
+			meo             = MeOverride,
+			cache           = Cache, 
+			cache_tmr       = CacheGcTimer, 
+			cache_autogc    = CacheAutoGC,
+			cache_gclimit   = CacheGcLimit,
+			cache_age       = CacheAge, 
+			cache_gcverbose = CacheGcVerb,
+			data_mod        = MibDataMod}};
 	{'aborted at', Mib, _NewData, Reason} ->
 	    ?vinfo("failed loading mib ~p: ~p",[Mib,Reason]),
 	    {error, {Mib, Reason}}
@@ -418,9 +433,43 @@ handle_call({update_cache_opts, Key, Value}, _From, State) ->
     {Result, NewState} = handle_update_cache_opts(Key, Value, State),
     {reply, Result, NewState};
 
+
+handle_call({subscribe_gc_events, Pid}, _From,
+            #state{cache_sub = Sub} = State)
+  when (Sub =:= undefined) ->
+    ?vdebug("subscribe_gc_events: ~p => ok", [Pid]), 
+    {reply, ok, State#state{cache_sub = Pid}};
+handle_call({subscribe_gc_events, Pid}, _From,
+            #state{cache_sub = Pid} = State) ->
+    ?vinfo("subscribe_gc_events: ~p => error:already-subscribed", [Pid]), 
+    {reply, {error, already_subscribed}, State};
+handle_call({subscribe_gc_events, Pid}, _From,
+            #state{cache_sub = Sub} = State)
+  when is_pid(Sub) andalso (Pid =/= Sub) ->
+    ?vinfo("subscribe_gc_events: ~p => error:already-subscribed ~p",
+           [Pid, Sub]), 
+    {reply, {error, {already_subscribed, Sub}}, State};
+
+handle_call({unsubscribe_gc_events, Pid}, _From,
+            #state{cache_sub = Pid} = State) ->
+    ?vdebug("unsubscribe_gc_events: ~p => ok", [Pid]), 
+    {reply, ok, State#state{cache_sub = undefined}};
+handle_call({unsubscribe_gc_events, Pid}, _From,
+            #state{cache_sub = Sub} = State)
+  when (Sub =:= undefined) ->
+    ?vinfo("unsubscribe_gc_events: ~p => error:not-subscribed", [Pid]), 
+    {reply, {error, not_subscribed}, State};
+handle_call({unsubscribe_gc_events, Pid}, _From,
+            #state{cache_sub = Sub} = State)
+  when is_pid(Sub) andalso (Pid =/= Sub) ->
+    ?vinfo("unsubscribe_gc_events: ~p => error:not-subscribed ~p",
+           [Pid, Sub]), 
+    {reply, {error, {not_subscribed, Sub}}, State};
+
+
 handle_call({lookup, Oid}, _From, 
 	    #state{data = Data, cache = Cache, data_mod = Mod} = State) ->
-    ?vlog("lookup ~p", [Oid]), 
+    ?vlog("lookup ~p", [Oid]),
     Key = {lookup, Oid}, 
     {Reply, NewState} = 
 	case maybe_cache_lookup(Cache, Key) of
@@ -431,7 +480,7 @@ handle_call({lookup, Oid}, _From,
 		ets:insert(Cache, {Key, Rep, timestamp()}),
 		{Rep, maybe_start_cache_gc_timer(State)};
 	    [{Key, Rep, _}] ->
-		?vdebug("lookup -> found in cache", []), 
+		?vtrace("lookup -> found in cache - update timestamp", []),
 		ets:update_element(Cache, Key, {3, timestamp()}),
 		{Rep, State}
 	end,
@@ -458,7 +507,7 @@ handle_call({next, Oid, MibView}, _From,
 		ets:insert(Cache, {Key, Rep, timestamp()}),
 		{Rep, maybe_start_cache_gc_timer(State)};
 	    [{Key, Rep, _}] ->
-		?vdebug("lookup -> found in cache", []), 
+		?vdebug("lookup -> found in cache - update timestamp", []),
 		ets:update_element(Cache, Key, {3, timestamp()}),
 		{Rep, State}
 	end,
@@ -570,7 +619,7 @@ handle_call(info, _From, #state{data     = Data,
     Reply = 
 	case (catch Mod:info(Data)) of
 	    Info when is_list(Info) ->
-		[{cache, size_cache(Cache)} | Info];
+		[{cache, cache_info(Cache)} | Info];
 	    E ->
 		    [{error, E}]
 	    end,
@@ -664,13 +713,21 @@ handle_info({backup_done, Reply}, #state{backup = {_, From}} = S) ->
     gen_server:reply(From, Reply),
     {noreply, S#state{backup = undefined}};
 
-handle_info(?CACHE_GC_TRIGGER, #state{cache         = Cache, 
-				      cache_age     = Age, 
-				      cache_gclimit = GcLimit, 
-				      cache_autogc  = true} = S) 
+handle_info(?CACHE_GC_TRIGGER, #state{cache           = Cache, 
+				      cache_age       = Age, 
+				      cache_gclimit   = GcLimit, 
+				      cache_autogc    = true,
+                                      cache_gcverbose = GcVerbose} = S) 
   when (Cache =/= ?NO_CACHE) ->
-    ?vlog("cache gc trigger event", []),
-    maybe_gc_cache(Cache, Age, GcLimit), 
+    gcvprint(GcVerbose, "GC: begin"),
+    case maybe_gc_cache(Cache, Age, GcLimit) of
+        {ok, NumDeleted} = Result when (NumDeleted > 0) ->
+            gcvprint(GcVerbose,
+                     "GC: ~w elements deleted from cache", [NumDeleted]),
+            maybe_send_gc_result(S, Result);
+        _ ->
+            ok
+    end,
     Tmr = start_cache_gc_timer(),
     {noreply, S#state{cache_tmr = Tmr}};
 
@@ -749,14 +806,15 @@ get_cacheopt_autogc(Cache, CacheOpts) ->
 		 IsValid).
 
 get_cacheopt_gclimit(Cache, CacheOpts) ->
-    IsValid = fun(Limit) when ((is_integer(Limit) andalso (Limit > 0)) orelse 
-			       (Limit =:= infinity)) ->
+    IsValid = fun(Limit) when ((is_integer(Limit) andalso
+                               (Limit > 0)) orelse
+                              (Limit =:= infinity)) ->
 		      true;
 		 (_) ->
 		      false
 	      end,
-    get_cacheopt(Cache, gclimit, CacheOpts, 
-		 infinity, ?DEFAULT_CACHE_GCLIMIT, 
+    get_cacheopt(Cache, gclimit, CacheOpts,
+		 infinity, ?DEFAULT_CACHE_GCLIMIT,
 		 IsValid).
 
 get_cacheopt_age(Cache, CacheOpts) ->
@@ -765,8 +823,18 @@ get_cacheopt_age(Cache, CacheOpts) ->
 		 (_) ->
 		      false
 	      end,
-    get_cacheopt(Cache, age, CacheOpts, 
-		 ?DEFAULT_CACHE_AGE, ?DEFAULT_CACHE_AGE, 
+    get_cacheopt(Cache, age, CacheOpts,
+		 ?DEFAULT_CACHE_AGE, ?DEFAULT_CACHE_AGE,
+		 IsValid).
+
+get_cacheopt_gcverbose(Cache, CacheOpts) ->
+    IsValid = fun(Verbosity) when is_boolean(Verbosity) ->
+		      true;
+		 (_) ->
+		      false
+	      end,
+    get_cacheopt(Cache, gcverbose, CacheOpts,
+		 ?DEFAULT_CACHE_GCVERBOSE, ?DEFAULT_CACHE_GCVERBOSE,
 		 IsValid).
 
 get_cacheopt(?NO_CACHE, _, _, NoCacheVal, _, _) ->
@@ -843,21 +911,28 @@ start_cache_gc_timer() ->
 
 %% ----------------------------------------------------------------
 
+gcvprint(GcVerbose, F) ->
+    gcvprint(GcVerbose, F, []).
+
+gcvprint(true, F, A) ->
+    ?vinfo(F, A);
+gcvprint(_, _, _) ->
+    ok.
+
 maybe_gc_cache(?NO_CACHE, _Age) ->
     ?vtrace("cache not enabled", []),
     ok;
 maybe_gc_cache(Cache, Age) ->
-    MatchSpec = gc_cache_matchspec(Age), 
-    Keys = ets:select(Cache, MatchSpec),
-    do_gc_cache(Cache, Keys),
-    {ok, length(Keys)}.
+    MatchSpec  = gc_cache_matchspec_del(Age),
+    NumDeleted = ets:select_delete(Cache, MatchSpec),
+    {ok, NumDeleted}.
 
 maybe_gc_cache(?NO_CACHE, _Age, _GcLimit) ->
     ok;
 maybe_gc_cache(Cache, Age, infinity = _GcLimit) ->
     maybe_gc_cache(Cache, Age);
 maybe_gc_cache(Cache, Age, GcLimit) ->
-    MatchSpec = gc_cache_matchspec(Age), 
+    MatchSpec = gc_cache_matchspec_key(Age), 
     Keys = 
 	case ets:select(Cache, MatchSpec, GcLimit) of
 	    {Match, _Cont} ->
@@ -868,14 +943,26 @@ maybe_gc_cache(Cache, Age, GcLimit) ->
     do_gc_cache(Cache, Keys),
     {ok, length(Keys)}.
 
-gc_cache_matchspec(Age) ->
-    Oldest    = timestamp() - Age,
+gc_cache_matchspec_del(Age) ->
+    %% The entry is a 3-tuple: {Key, Value, Timestamp}
+    MatchHead = {'_', '_', '$2'}, 
+    Return    = true,
+    gc_cache_matchspec(Age, MatchHead, Return).
+
+gc_cache_matchspec_key(Age) ->
+    %% The entry is a 3-tuple: {Key, Value, Timestamp}
     MatchHead = {'$1', '_', '$2'}, 
+    Return    = '$1',
+    gc_cache_matchspec(Age, MatchHead, Return).
+
+gc_cache_matchspec(Age, MatchHead, Return) ->
+    Oldest    = timestamp() - Age,
     Guard     = [{'<', '$2', Oldest}], 
-    MatchFunc = {MatchHead, Guard, ['$1']},
+    MatchFunc = {MatchHead, Guard, [Return]},
     MatchSpec = [MatchFunc],
     MatchSpec.
 
+
 do_gc_cache(_, []) ->
     ok;
 do_gc_cache(Cache, [Key|Keys]) ->
@@ -906,20 +993,37 @@ maybe_cache_lookup(?NO_CACHE, _) ->
 maybe_cache_lookup(Cache, Key) ->
     ets:lookup(Cache, Key).
 
-size_cache(?NO_CACHE) ->
+
+cache_info(?NO_CACHE) ->
     undefined;
-size_cache(Cache) ->
-    case (catch ets:info(Cache, memory)) of
-	Sz when is_integer(Sz) ->
-	    Sz;
-	_ ->
-	    undefined
+cache_info(Cache) ->
+    try
+        begin
+            [
+             {memory, ets:info(Cache, memory)},
+             {size,   ets:info(Cache, size)},
+             {stats,  ets:info(Cache, stats)}
+            ]
+        end
+    catch
+        _:_:_ ->
+            undefined
     end.
 
+
 timestamp() ->
     snmp_misc:now(ms).
 
 
+maybe_send_gc_result(S, Result) ->
+    maybe_send_gc_event(S, gc_result, Result).
+
+maybe_send_gc_event(#state{cache_sub = Sub}, Ev, Info) when is_pid(Sub) ->
+    Sub ! {self(), Ev, Info};
+maybe_send_gc_event(_, _, _) ->
+    ok.
+
+
 %% ----------------------------------------------------------------
 
 get_opt(Key, Options) ->
diff --git a/lib/snmp/test/snmp_agent_mibs_SUITE.erl b/lib/snmp/test/snmp_agent_mibs_SUITE.erl
index 150e015554..6e2ee0d48c 100644
--- a/lib/snmp/test/snmp_agent_mibs_SUITE.erl
+++ b/lib/snmp/test/snmp_agent_mibs_SUITE.erl
@@ -182,7 +182,7 @@ init_per_testcase2(size_check_ets3_bad_file1, Config) when is_list(Config) ->
 init_per_testcase2(size_check_mnesia, Config) when is_list(Config) ->
     Config;
 init_per_testcase2(cache_test, Config) when is_list(Config) ->
-    Min = timer:minutes(5), 
+    Min = ?MINS(10), 
     Timeout =
 	case lists:keysearch(tc_timeout, 1, Config) of
 	    {value, {tc_timeout, TcTimeout}} when TcTimeout < Min ->
@@ -574,9 +574,10 @@ which_mib(Config) when is_list(Config) ->
 
 cache_test(suite) -> [];
 cache_test(Config) when is_list(Config) ->
-    ?DBG("cache_test -> start", []),
+    ?IPRINT("cache_test -> start"),
     Prio       = normal,
-    Verbosity  = trace,
+    %% Verbosity  = trace,
+    Verbosity  = info,
     MibStorage = [{module, snmpa_mib_storage_ets}],
     MibDir     = ?config(data_dir, Config),
     StdMibDir  = filename:join(code:priv_dir(snmp), "mibs") ++ "/",
@@ -587,94 +588,303 @@ cache_test(Config) when is_list(Config) ->
 		  "SNMP-MPD-MIB",
 		  "SNMP-NOTIFICATION-MIB",
 		  "SNMP-TARGET-MIB",
-		  %% "SNMP-USER-BASED-SM-MIB",
+		  "SNMP-USER-BASED-SM-MIB",
 		  "SNMP-VIEW-BASED-ACM-MIB",
 		  "SNMPv2-MIB",
 		  "SNMPv2-TC",
 		  "SNMPv2-TM"],
 
-    ?DBG("cache_test -> start symbolic store", []),
-    ?line sym_start(Prio, MibStorage, Verbosity),
+    ?IPRINT("cache_test -> start symbolic store"),
+    ?line sym_start(Prio, MibStorage, silence), % Verbosity),
 
-    ?DBG("cache_test -> start mib server", []),
-    GcLimit   = 2, 
-    Age       = timer:seconds(10), 
-    CacheOpts = [{autogc, false}, {age, Age}, {gclimit, GcLimit}],
+    ?IPRINT("cache_test -> start mib server"),
+    GcLimit   = 3,
+    Age       = timer:seconds(10),
+    CacheOpts = [{autogc,    false},
+                 {age,       Age},
+                 {gclimit,   GcLimit},
+                 {gcverbose, true}],
     ?line MibsPid = mibs_start(Prio, MibStorage, [], Verbosity, CacheOpts), 
     
-    ?DBG("cache_test -> load mibs", []),
+    ?NPRINT("Info before load mibs: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    ?IPRINT("cache_test -> load mibs"),
     ?line load_mibs(MibsPid, MibDir, Mibs),
-    ?DBG("cache_test -> load std mibs", []),
+
+    ?NPRINT("Info before load std mibs: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    ?IPRINT("cache_test -> load std mibs"),
     ?line load_mibs(MibsPid, StdMibDir, StdMibs),
 
-    ?DBG("cache_test -> do a simple walk to populate the cache", []),
-    ?line ok = walk(MibsPid),
-     
-    {ok, Sz1} = snmpa_mib:which_cache_size(MibsPid),
-    ?DBG("cache_test -> Size1: ~p", [Sz1]),
+    ?NPRINT("Info (after mibs load but) before populate: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    ?IPRINT("cache_test -> populate the cache"),
+    ?line ok = populate(MibsPid),
 
-    ?DBG("cache_test -> sleep 5 secs", []),
+    ?NPRINT("Info after populate: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    Sz1 = cache_sz_verify(1, MibsPid, any),
+
+    ?IPRINT("cache_test -> sleep 5 secs"),
     ?SLEEP(timer:seconds(5)),
 
-    ?DBG("cache_test -> perform gc, expect nothing", []),
-    {ok, 0} = snmpa_mib:gc_cache(MibsPid),
+    _ = cache_gc_verify(1, MibsPid),
+
+    ?NPRINT("Info after 5 sec sleep: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
 
-    ?DBG("cache_test -> sleep 10 secs", []),
+    ?IPRINT("cache_test -> sleep 10 secs"),
     ?SLEEP(timer:seconds(10)),
 
-    ?DBG("cache_test -> perform gc, expect GcLimit", []),
-    GcLimit1 = GcLimit + 1, 
-    {ok, GcLimit1} = snmpa_mib:gc_cache(MibsPid, Age, GcLimit1),
+    ?NPRINT("Info after 10 sec sleep: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    GcLimit1 = cache_gc_verify(2, MibsPid, Age, GcLimit + 1),
+
+    Sz2 = cache_sz_verify(2, MibsPid, Sz1 - GcLimit1),
+
 
-    Sz2 = Sz1 - GcLimit1, 
-    {ok, Sz2} = snmpa_mib:which_cache_size(MibsPid),
-    ?DBG("cache_test -> Size2: ~p", [Sz2]),
+    ?IPRINT("cache_test -> subscribe to GC events"),
+    ?line ok = snmpa_mib:subscribe_gc_events(MibsPid),
 
-    ?DBG("cache_test -> enable cache autogc", []),
+    ?IPRINT("cache_test -> enable cache autogc"),
     ?line ok = snmpa_mib:enable_cache_autogc(MibsPid),
 
-    ?DBG("cache_test -> wait 65 seconds to allow gc to happen", []),
+    ?IPRINT("cache_test -> wait 65 seconds to allow gc to happen"),
     ?SLEEP(timer:seconds(65)),
-    Sz3 = Sz2 - GcLimit, 
-    {ok, Sz3} = snmpa_mib:which_cache_size(MibsPid),
-    ?DBG("cache_test -> Size3: ~p", [Sz3]),
 
-    ?DBG("cache_test -> "
-	 "wait 2 minutes to allow gc to happen, expect empty cache", []),
+    ?NPRINT("Info after 65 sec sleep: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    ?IPRINT("cache_test -> [1] flush expected GC events"),
+    {NumEvents1, TotGC1} = cache_flush_gc_events(MibsPid),
+    ?IPRINT("cache_test -> GC events: "
+            "~n      Number of Events:    ~p"
+            "~n      Total elements GCed: ~p", [NumEvents1, TotGC1]),
+
+    _ = cache_sz_verify(3, MibsPid, Sz2 - GcLimit),
+
+    ?IPRINT("cache_test -> "
+            "wait 2 minutes to allow gc to happen, expect empty cache"),
     ?SLEEP(timer:minutes(2)),
-    {ok, 0} = snmpa_mib:which_cache_size(MibsPid),
 
-    ?DBG("cache_test -> stop mib server", []),
+    ?NPRINT("Info after 2 min sleep: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    _ = cache_sz_verify(4, MibsPid, 0),
+
+
+    ?IPRINT("cache_test -> change gclimit to infinity"),
+    snmpa_mib:update_cache_gclimit(MibsPid, infinity),
+
+    ?IPRINT("cache_test -> change age to ~w mins", [3]),
+    snmpa_mib:update_cache_age(MibsPid, ?MINS(3)),
+
+    ?IPRINT("cache_test -> [2] flush expected GC events"),
+    {NumEvents2, TotGC2} = cache_flush_gc_events(MibsPid),
+    ?IPRINT("cache_test -> GC events: "
+            "~n      Number of Events:    ~p"
+            "~n      Total elements GCed: ~p", [NumEvents2, TotGC2]),
+
+    ?IPRINT("cache_test -> populate the cache again"),
+    populate(MibsPid),
+
+    ?IPRINT("cache_test -> validate cache size"),
+    {ok, Sz4} = snmpa_mib:which_cache_size(MibsPid),
+    if (Sz4 > 0) ->
+            ?IPRINT("cache_test -> expected cache size: ~w > 0", [Sz4]);
+       true      ->
+            ?EPRINT("cache_test -> cache *not* populated"),
+            ?FAIL(cache_not_populated)
+    end,    
+
+    ?NPRINT("Info after poulated: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    ?IPRINT("cache_test -> wait 2 mins - before tuching some entries"),
+    ?SLEEP(?MINS(2)),
+
+    %% There should not be anything GC:ed
+
+    receive
+        {MibsPid, gc_result, {ok, NGC1}} ->
+            ?EPRINT("cache_test -> unexpected GC of ~w elements", [NGC1]),
+            exit({unexpected_gc_result, NGC1})
+    after 0 ->
+            ok
+    end,
+
+    ?IPRINT("cache_test -> touch some elements again (update the cache)"),
+    populate_lookup(MibsPid),
+
+    ?IPRINT("cache_test -> await partial GC"),
+    NumGC2 =
+        receive
+            {MibsPid, gc_result, {ok, NGC2}} 
+              when (NGC2 > 0) andalso (Sz4 > NGC2) ->
+                ?NPRINT("cache_test -> "
+                        "received partial GC result of ~w elements", [NGC2]),
+                NGC2
+        end,
+
+    ?NPRINT("Info after partial GC: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+
+    ?IPRINT("cache_test -> await final GC"),
+    receive
+        {MibsPid, gc_result, {ok, NGC3}} 
+          when (NGC3 > 0) andalso ((Sz4 - NumGC2) =:= NGC3) ->
+            ?NPRINT("cache_test -> "
+                    "received final GC result of ~w elements", [NGC3]),
+            NGC3;
+        Any ->
+            ?EPRINT("cache_test -> unexpected message: "
+                    "~n      ~p", [Any]),
+            ?FAIL({unexpected, Any})
+    end,
+
+    ?NPRINT("Info after final GC: "
+            "~n      ~p", [snmpa_mib:info(MibsPid)]),
+
+    ?IPRINT("cache_test -> validate cache size (expect empty)"),
+    {ok, Sz5} = snmpa_mib:which_cache_size(MibsPid),
+    if (Sz5 =:= 0) ->
+            ?IPRINT("cache_test -> expected cache size: 0");
+       true      ->
+            ?EPRINT("cache_test -> cache *not* empty (~w)", [Sz5]),
+            ?FAIL({cache_populated, Sz5})
+    end,
+
+
+    ?IPRINT("cache_test -> stop mib server"),
     ?line mibs_stop(MibsPid),
 
-    ?DBG("cache_test -> stop symbolic store", []),
+    ?IPRINT("cache_test -> stop symbolic store"),
     ?line sym_stop(),
+
+    ?IPRINT("cache_test -> end"),
     ok.
 
-walk(MibsPid) ->
+populate(MibsPid) ->
+    %% Make some lookups
+    populate_lookup(MibsPid),
+    %% Make some walk's
+    populate_walk(MibsPid).
+
+populate_lookup(MibsPid) ->    
+    {variable, _} = snmpa_mib:lookup(MibsPid, ?snmpTrapCommunity_instance),
+    {variable, _} = snmpa_mib:lookup(MibsPid, ?vacmViewSpinLock_instance),
+    {variable, _} = snmpa_mib:lookup(MibsPid, ?usmStatsNotInTimeWindows_instance),
+    {variable, _} = snmpa_mib:lookup(MibsPid, ?tDescr_instance),
+    ok.
+
+populate_walk(MibsPid) ->
     MibView = snmpa_acm:get_root_mib_view(),
-    do_walk(MibsPid, ?snmpTrapCommunity_instance, MibView),
-    do_walk(MibsPid, ?vacmViewSpinLock_instance, MibView),
-    do_walk(MibsPid, ?usmStatsNotInTimeWindows_instance, MibView),
-    do_walk(MibsPid, ?tDescr_instance, MibView).
-    
+    walk(MibsPid, ?snmpTrapCommunity_instance,        MibView),
+    walk(MibsPid, ?vacmViewSpinLock_instance,         MibView),
+    walk(MibsPid, ?usmStatsNotInTimeWindows_instance, MibView),
+    walk(MibsPid, ?tDescr_instance,                   MibView),
+    ok.
+
+walk(MibsPid, Oid, MibView) ->
+    ?IPRINT("walk -> entry with"
+            "~n      Oid: ~p", [Oid]),
+    do_walk(MibsPid, Oid, MibView).
 
 do_walk(MibsPid, Oid, MibView) ->
-    io:format("do_walk -> entry with"
-	      "~n   Oid: ~p"
-	      "~n", [Oid]),
     case snmpa_mib:next(MibsPid, Oid, MibView) of
 	{table, _, _, #me{oid = Oid}} ->
+            ?IPRINT("do_walk -> table done"),
 	    ok;
 	{table, _, _, #me{oid = Next}} ->
+            ?IPRINT("do_walk -> table next ~p", [Next]),
 	    do_walk(MibsPid, Next, MibView);
 	{variable, #me{oid = Oid}, _} ->
+            ?IPRINT("do_walk -> variable done"),
 	    ok;
 	{variable, #me{oid = Next}, _} ->
+            ?IPRINT("do_walk -> variable next ~p", [Next]),
 	    do_walk(MibsPid, Next, MibView)
     end.
 
 
+cache_gc_verify(ID, MibsPid) ->
+    GC = fun() -> snmpa_mib:gc_cache(MibsPid) end,
+    cache_gc_verify(ID, GC, 0).
+
+cache_gc_verify(ID, MibsPid, Age, ExpectedGcLimit) ->
+    GC = fun() -> snmpa_mib:gc_cache(MibsPid, Age, ExpectedGcLimit) end,
+    cache_gc_verify(ID, GC, ExpectedGcLimit).
+
+cache_gc_verify(ID, GC, ExpectedGc) ->
+    ?IPRINT("cache_gc_verify -> [~w] perform gc, expect ~w", [ID, ExpectedGc]),
+    case GC() of
+        {ok, ExpectedGc} ->
+            ?IPRINT("cache_gc_verify -> [~w] gc => ok", [ID]),
+            ExpectedGc;
+        {ok, OtherGc} ->
+            ?IPRINT("cache_gc_verify -> [~w] invalid GC limit: "
+                    "~n      Expected: ~p"
+                    "~n      Got:      ~p"
+                    "~n      ~p",
+                    [ID, 0, OtherGc]),
+            exit({ID, invalid_gc_limit, {ExpectedGc, OtherGc}});
+        Unexpected ->
+            ?IPRINT("cache_gc_verify -> [~w] unexpected: "
+                    "~n      ~p",
+                    [ID, Unexpected]),
+            exit({ID, unexpected, Unexpected})
+    end.
+
+
+cache_sz_verify(ID, MibsPid, ExpectedSz) ->
+    ?IPRINT("cache_sz_verify -> [~w] expect size ~w", [ID, ExpectedSz]),
+    case snmpa_mib:which_cache_size(MibsPid) of
+        {ok, ExpectedSz} ->
+            ?IPRINT("cache_sz_verify -> [~w] sz => ok", [ID]),
+            ExpectedSz;
+        {ok, UnexpectedSz} when (ExpectedSz =:= any) ->
+            ?IPRINT("cache_sz_verify -> [~w] sz => ok (~w)", [ID, UnexpectedSz]),
+            UnexpectedSz;
+        {ok, UnexpectedSz} ->
+            ?IPRINT("cache_sz_verify -> [~w] invalid size: "
+                    "~n      Expected: ~p"
+                    "~n      Got:      ~p",
+                    [ID, ExpectedSz, UnexpectedSz]),
+            exit({ID, invalid_size, {ExpectedSz, UnexpectedSz}});
+        Unexpected ->
+            ?IPRINT("cache_sz_verify -> [~w] unexpected: "
+                    "~n      ~p",
+                    [ID, Unexpected]),
+            exit({ID, unexpected, Unexpected})
+    end.
+
+
+cache_flush_gc_events(MibServer) ->
+    cache_flush_gc_events(MibServer, 0, 0).
+
+cache_flush_gc_events(MibServer, NumEvents, TotGC) ->
+    receive
+        {MibServer, gc_result, {ok, NumGC}} ->
+            ?IPRINT("cache_flush_gc_events -> GC event ~w (~w)",
+                    [NumGC, NumEvents]),
+            cache_flush_gc_events(MibServer, NumEvents+1, TotGC+NumGC)
+    after 0 ->
+            if
+                (NumEvents =:= 0) andalso (TotGC =:= 0) ->
+                    ?IPRINT("cache_flush_gc_events -> no GC events"),
+                    exit(no_gc_events);
+                true ->
+                    {NumEvents, TotGC}
+            end
+    end.
+
+
 %%======================================================================
 %% Internal functions
 %%======================================================================