Service crash on Redis 3.0.500 (7th Dec 2015) EXCEPTION_ACCESS_VIOLATION

[DavidADoran]

I was seeing these errors with the previous, RC2, version so have just updated and can still reproducibly cause the service to crash.

The crash dump is pasted below. It's happened on several machines so I don't suspect memory faults.

Originally I was working within a component I've been developing but decided to isolate the problem using the code below. This is C# using the NuGet package StackExchange.Redis.StrongName, version 1.0.488. Usually takes between 5 and 100 calls to StressRedis() to provoke failure.

static class Program
{
    public static void Main()
    {
        var connection = ConnectionMultiplexer.Connect("localhost,syncTimeout=5000");
        var i = 0;
        while (true)
        {
            ++i;
            Console.WriteLine("Stressing Redis. Run " + i);
            StressRedis(connection);
        }
    }

    private static void StressRedis(IConnectionMultiplexer connection)
    {
        var db = connection.GetDatabase();
        var ids = new List<string>();
        for (var i = 0; i < 10000; i++)
        {
            var id = Guid.NewGuid().ToString();
            ids.Add(id);
            db.StringSet(id, "Test");
        }

        foreach (var id in ids)
        {
            db.KeyDelete(id);
        }
    }
}

Regards,
David Doran

=== REDIS BUG REPORT START: Cut & paste starting from here ===
[1332] 14 Dec 14:29:35.253 # Redis version: 3.0.500
[1332] 14 Dec 14:29:35.253 # --- EXCEPTION_ACCESS_VIOLATION
[1332] 14 Dec 14:29:35.253 # --- STACK TRACE
redis-server.exe!LogStackTrace(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:95)(0x012CE690, 0x012CFF90, 0x00000001, 0x40123730)
redis-server.exe!UnhandledExceptiontHandler(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x00000001, 0x00000000, 0x00000001, 0xFD7AABC0)
kernel32.dll!UnhandledExceptionFilter(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x012CE690, 0x00000006, 0x00000000, 0x00000001)
ntdll.dll!EtwEventSetInformation(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x012CF2D0, 0x00000000, 0x401297C8, 0x00000000)
ntdll.dll!_C_specific_handler(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x012D0000, 0x012CFF90, 0x012CFF90, 0x774AEAAC)
ntdll.dll!RtlDecodePointer(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x012D0000, 0x7725EDAC, 0x00012A98, 0x000001B0)
ntdll.dll!RtlUnwindEx(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x012CF2D0, 0x012CEDE0, 0x00000000, 0x00000000)
ntdll.dll!KiUserExceptionDispatcher(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x40032F9B, 0xFFFFFFE0, 0xF50F1000, 0x02811B9A)
redis-server.exe!je_bitmap_set(c:\release\redis\deps\jemalloc-win\include\jemalloc\internal\bitmap.h:101)(0xFFFFFFE0, 0xF50F1000, 0x02811B9A, 0x02811B9B)
redis-server.exe!arena_run_reg_alloc(c:\release\redis\deps\jemalloc-win\src\arena.c:289)(0x00000000, 0xF4C00250, 0x00000020, 0x40170F10)
redis-server.exe!je_arena_malloc_small(c:\release\redis\deps\jemalloc-win\src\arena.c:1608)(0xF506E290, 0x012CF570, 0x00000010, 0x00000011)
redis-server.exe!je_arena_ralloc(c:\release\redis\deps\jemalloc-win\src\arena.c:2180)(0x012CF570, 0x00000011, 0x00000010, 0x0000000F)
redis-server.exe!je_iralloct(c:\release\redis\deps\jemalloc-win\include\jemalloc\internal\jemalloc_internal.h:1023)(0x00000011, 0x00000010, 0x00000020, 0x40170F10)
redis-server.exe!je_realloc(c:\release\redis\deps\jemalloc-win\src\jemalloc.c:1302)(0x00000010, 0x00000020, 0x00000011, 0x00000000)
redis-server.exe!zrealloc(c:\release\redis\src\zmalloc.c:179)(0x00000008, 0x00000004, 0x02811AD8, 0x00000000)
redis-server.exe!sdscatlen(c:\release\redis\src\sds.c:248)(0xF506E298, 0x4015E7B0, 0x00000000, 0xF50F1220)
redis-server.exe!catAppendOnlyGenericCommand(c:\release\redis\src\aof.c:462)(0x00000003, 0x02811AB8, 0x00000000, 0xF50F1FA0)
redis-server.exe!feedAppendOnlyFile(c:\release\redis\src\aof.c:544)(0x000264E1, 0xDAF07CEC, 0x00000007, 0x4008DB5C)
redis-server.exe!call(c:\release\redis\src\redis.c:2163)(0x566ED24F, 0x400A4CF0, 0x566ED24F, 0x0000000B)
redis-server.exe!processCommand(c:\release\redis\src\redis.c:2368)(0x00000004, 0x0000000B, 0x00000000, 0x00000000)
redis-server.exe!processInputBuffer(c:\release\redis\src\networking.c:1291)(0x00000000, 0x0000000B, 0x00000042, 0x00000000)
redis-server.exe!readQueryFromClient(c:\release\redis\src\networking.c:1344)(0xF506F160, 0x00000001, 0xF5018150, 0x000000E4)
redis-server.exe!aeMain(c:\release\redis\src\ae.c:481)(0x566ED0B1, 0xF5006FA8, 0x00000002, 0x00288E40)
redis-server.exe!redis_main(c:\release\redis\src\redis.c:3765)(0x00000000, 0x00283160, 0x566ED093, 0x00288E40)
redis-server.exe!main(c:\release\redis\src\win32_interop\win32_qfork.cpp:1241)(0x00000016, 0xFFFFFFFF, 0x00000016, 0x00000000)
redis-server.exe!ServiceWorkerThread(c:\release\redis\src\win32_interop\win32_service.cpp:484)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
kernel32.dll!BaseThreadInitThunk(c:\release\redis\src\win32_interop\win32_service.cpp:484)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!RtlUserThreadStart(c:\release\redis\src\win32_interop\win32_service.cpp:484)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!RtlUserThreadStart(c:\release\redis\src\win32_interop\win32_service.cpp:484)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
[1332] 14 Dec 14:29:35.283 # --- INFO OUTPUT

Server

redis_version:3.0.500
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:e18d443f4404273c
redis_mode:standalone
os:Windows
arch_bits:64
multiplexing_api:WinSock_IOCP
process_id:1332
run_id:9518e8586af6b72bcf4cdde7f9006d445ac9482a
tcp_port:6379
uptime_in_seconds:444
uptime_in_days:0
hz:10
lru_clock:7262799
config_file:C:\Program Files\Redis\redis.windows-service.conf

Clients

connected_clients:4
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0

Memory

used_memory:781520
used_memory_human:763.20K
used_memory_rss:849488
used_memory_peak:12633048
used_memory_peak_human:12.05M
used_memory_lua:36864
mem_fragmentation_ratio:1.09
mem_allocator:jemalloc-3.6.0

Persistence

loading:0
rdb_changes_since_last_save:156898
rdb_bgsave_in_progress:0
rdb_last_save_time:1450103343
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:-1
aof_enabled:1
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_last_write_status:ok
aof_current_size:637589141
aof_base_size:590005669
aof_pending_rewrite:0
aof_buffer_length:0
aof_rewrite_buffer_length:0
aof_pending_bio_fsync:0
aof_delayed_fsync:0

Stats

total_connections_received:4
total_commands_processed:780275
instantaneous_ops_per_sec:5865
total_net_input_bytes:47590366
total_net_output_bytes:46178045
instantaneous_input_kbps:321.00
instantaneous_output_kbps:22.94
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
evicted_keys:0
keyspace_hits:0
keyspace_misses:2
pubsub_channels:1
pubsub_patterns:0
latest_fork_usec:123012
migrate_cached_sockets:0

Replication

role:master
connected_slaves:0
master_repl_offset:0
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

CPU

used_cpu_sys:64.04
used_cpu_user:43.29
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

Commandstats

cmdstat_get:calls=2,usec=0,usec_per_call=0.00
cmdstat_set:calls=390053,usec=1681171,usec_per_call=4.31
cmdstat_del:calls=390000,usec=1481153,usec_per_call=3.80
cmdstat_select:calls=4,usec=0,usec_per_call=0.00
cmdstat_scan:calls=70,usec=380032,usec_per_call=5429.03
cmdstat_ping:calls=130,usec=0,usec_per_call=0.00
cmdstat_echo:calls=2,usec=0,usec_per_call=0.00
cmdstat_flushdb:calls=1,usec=4001,usec_per_call=4001.00
cmdstat_info:calls=5,usec=0,usec_per_call=0.00
cmdstat_config:calls=3,usec=0,usec_per_call=0.00
cmdstat_subscribe:calls=1,usec=0,usec_per_call=0.00
cmdstat_unsubscribe:calls=2,usec=0,usec_per_call=0.00
cmdstat_cluster:calls=1,usec=0,usec_per_call=0.00
cmdstat_client:calls=2,usec=0,usec_per_call=0.00

Cluster

cluster_enabled:0

Keyspace

db0:keys=53,expires=0,avg_ttl=0
[1332] 14 Dec 14:29:35.284 #
=== REDIS BUG REPORT END. Make sure to include from START to END. ===

[enricogior]

Hi @DavidADoran,
thank you for reporting the issue.
Can you please post the log just before the crash?
It would also help to see the config file in case you changed the default configuration, since I'm currently unable to reproduce the crash.
Thank you.

[DavidADoran]

Hi, I'll attach the log and config file. Thanks for the fast response.
Regards,
David.

redis_log.txt

redis.windows-service.conf.txt

[enricogior]

@DavidADoran
thank you.

[enricogior]

@DavidADoran
I forgot to ask you on what Windows version are you experiencing the problem.
Virtual or physical machine?
Thank you.

[DavidADoran]

The log I posted above is from my dev box. Physical x64 PC, Windows 7 (6.1) Enterprise Edition Service Pack 1 (Build 7601)

Other failures have been on my test VMs, which are Windows Server 2012 R2 (x64).

Thanks,
David.

[enricogior]

@DavidADoran
ok good, I'm currently trying to reproduce the bug on the same machines: physical Windows 7 and VM Windows Server 2012 R2.
I'll let you know my finding, so far from the log we know it's a problem with jemalloc, but it may be a problem somewhere causing the error in jemalloc.

[DavidADoran]

Hi Enrico, did you manage to reproduce this in the end?
Thanks,
David.

[enricogior]

@DavidADoran
not yet, I've been running the stress code for hours on both Windows 7 and Windows Server 2012 R2 without errors. I also tried increasing the number of keys to 100,000 and still no errors.

[DavidADoran]

OK, thanks. I'll create a few VMs of various types tomorrow to see if I can find any clues about what environment (CPU count for example) might determine ability to reproduce this.

Thanks,
David.

[DavidADoran]

I've done some more testing today with some fresh VMs. Again Redis was installed from Redis-x64-3.0.500.msi, and this time running on Windows Server 2012 R2 (datacenter edition).

The crash is reproducible on there but only when using the configuration file I attached previously redis.windows-service.conf.txt (NOTE! Remove the .txt - I had to add that extension to get it accepted by GitHub)

The failure seems much more likely when the VM has more than one CPU. On a single CPU machine it sometimes took 1500 calls to StressRedis() to break. With two or more CPUs on the VM it typically took less than 100 calls to StressRedis() to break.

I hope this helps you reproduce the issue. Thanks again for looking at this.
Regards,
David.

[enricogior]

@DavidADoran
thanks for the extra info.

[johnwonder]

@enricogior

I have the problem here too.

[792] 24 Dec 15:34:46.789 # Redis version: 3.0.500
[792] 24 Dec 15:34:46.789 # --- EXCEPTION_ACCESS_VIOLATION
[792] 24 Dec 15:34:46.789 # --- STACK TRACE
redis-server.exe!LogStackTrace(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:95)(0x0012E730, 0x0012FF90, 0x00000001, 0x40123730)
redis-server.exe!UnhandledExceptiontHandler(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x00000001, 0x00000000, 0x00000001, 0x00570008)
kernel32.dll!UnhandledExceptionFilter(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x0012E730, 0x00000006, 0x00000000, 0x00000001)
ntdll.dll!MD5Final(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x0012F370, 0x00000000, 0x40129C28, 0x00000000)
ntdll.dll!_C_specific_handler(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x00130000, 0x0012FF90, 0x0012FF90, 0x77DB2DE8)
ntdll.dll!RtlDecodePointer(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x00130000, 0x77B5DF08, 0x00012F24, 0x00630158)
ntdll.dll!RtlUnwindEx(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0x0012F370, 0x0012EE80, 0x00000000, 0x00000000)
ntdll.dll!KiUserExceptionDispatcher(c:\release\redis\src\win32_interop\win32_stacktrace.cpp:185)(0xC7B93630, 0x000007D0, 0x0280D047, 0x00000001)
redis-server.exe!rdbSaveObjectType(c:\release\redis\src\rdb.c:456)(0x0012F6E0, 0x223A2265, 0xC7B93630, 0x00000001)
redis-server.exe!rdbSaveRio(c:\release\redis\src\rdb.c:694)(0x4014F210, 0x00EA0000, 0x00000005, 0x012A2754)
redis-server.exe!rdbSave(c:\release\redis\src\rdb.c:758)(0x00EA0000, 0x567B6B56, 0x00EA0000, 0x00000005)
redis-server.exe!QForkChildInit(c:\release\redis\src\win32_interop\win32_qfork.cpp:337)(0x00000005, 0x00000000, 0x002CCF50, 0x00000005)
redis-server.exe!QForkStartup(c:\release\redis\src\win32_interop\win32_qfork.cpp:515)(0x00000006, 0x00000000, 0x00000000, 0x002CC1C0)
redis-server.exe!main(c:\release\redis\src\win32_interop\win32_qfork.cpp:1240)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
redis-server.exe!__tmainCRTStartup(f:\dd\vctools\crt\crtw32\startup\crt0.c:255)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
kernel32.dll!BaseThreadInitThunk(f:\dd\vctools\crt\crtw32\startup\crt0.c:255)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!RtlUserThreadStart(f:\dd\vctools\crt\crtw32\startup\crt0.c:255)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!RtlUserThreadStart(f:\dd\vctools\crt\crtw32\startup\crt0.c:255)(0x00000000, 0x00000000, 0x00000000, 0x00000000)

[enricogior]

Hi @johnwonder
the log you posted shows a different problem.
Can you please open a new issue, adding the configuration file (if you made any change to the default config file) and describing your environment (OS, ram, virtual or physical etc.).
Can you provide repro steps for the crash?
Thank you.

[enricogior]

@DavidADoran
I'm still trying to reproduce the crash, I'm using a VM with 4 processor cores.
Beside Redis, do you run any other application/service/tool on the WM?
Did you change any significant default Windows Server configuration?
I suspect there might be some external configuration that makes easier to reproduce the crash.
Thank you.