Re: svn commit: r990537 - /subversion/branches/performance/subversion/libsvn_subr/svn_temp_serializer.c

Johan Corveleyn <jcorvel_at_gmail.com
<mailto:jcorvel_at_gmail.com?Subject=Re:%20svn%20commit:%20r990537%20-%20/subversion/branches/performance/subversion/libsvn_subr/svn_temp_serializer.c>>
wrote:

> On Sun, Aug 29, 2010 at 12:32 PM, <stefan2_at_apache.org> wrote:
> /> Author: stefan2 /
> /> Date: Sun Aug 29 10:32:08 2010 /
> /> New Revision: 990537 /
> /> /
> /> URL: http://svn.apache.org/viewvc?rev=990537&view=rev
> <http://svn.apache.org/viewvc?rev=990537&view=rev> /
> /> Log: /
> /> Looking for the cause of Johan Corveleyn's crash (see /
> /> http://svn.haxx.se/dev/archive-2010-08/0652.shtml), it /
> /> seems that wrong / corrupted data contains backward /
> /> pointers, i.e. negative offsets. That cannot happen if /
> /> everything works as intended. /
>
> I've just retried my test after this change (actually with
> performance-branch_at_990579, so updated just 10 minutes ago). Now I get
> the assertion error, after running log or blame on that particular
> file:
>
> [[[
> $ svnserve -d -r c:/research/svn/experiment/repos
> Assertion failed: *ptr > buffer, file
> ..\..\..\subversion\libsvn_subr\svn_temp_serializer.c, line 282
>
> This application has requested the Runtime to terminate it in an
> unusual way.
> Please contact the application's support team for more information.
> ]]]
>
That is what I expected looking at the call stacks you posted.
My preliminary analysis goes as follows:

* The error seems to be limited to relatively rare occasions.
  That sufficiently excludes alignment issues and plainly wrong
  parameters / function calls.

* It might be a (still rare) 32-bit-only issue.

* There seems to be no miscast of types, i.e. the DAG node
  being read and causing the PF is actually a DAG node. Even
  if conflicting keys were used, the structure could still be read
  from the cache and would lead to some logic failure elsewhere.

What else could it be? Most of the following are rather

* concurrency issue
* data corruption within the cache itself
* some strange serialization issue that needs very specific data
  and / or 32 bit pointers to show up

> Is there any way I can find more information about this failure, so I
> can help you diagnose the problem?
>
In fact there is. Just some questions:

* You are the only one accessing the server and you use
  a single client process?
* Does it happen if you log / blame the file for the first time
  and no other requests have been made to the server before?
* Does a command line "svn log" produce some output
  before the crash? If so, is there something unusual happening
  around these revisions (branch replacement or so)?

Also, please verify that the crash gets triggered if the server is started
with the following extra parameters:

* -c0 -M0 -F0
* -c0 -M0
* -c0 -M1500 -F0
* -c0 -M1500

>
>
> Just to be clear: the very same repos does not have this problem when
> accessed by a trunk svnserve.
I thought so ;) To narrow down the nature of the problem,
I added some checks that should be able to discern plain
data corruption from (de-)serialization issues. Please apply
either the patch or replace the original files with the versions
in the .zip file.

A debug build should then, hopefully, trigger a different
and more specific assertion.

-- Stefan^2.

Index: /home/stefan/develop/performance/subversion/libsvn_subr/svn_temp_serializer.c
===================================================================
--- /home/stefan/develop/performance/subversion/libsvn_subr/svn_temp_serializer.c (revision 990572)
+++ /home/stefan/develop/performance/subversion/libsvn_subr/svn_temp_serializer.c (working copy)
@@ -84,6 +84,10 @@
   if (aligned_len != current_len)
     {
       svn_stringbuf_ensure(context->buffer, aligned_len+1);
+ /* TODO remove this debug code */
+ {
+ memset(context->buffer->data + current_len, 0, aligned_len - current_len);
+ }
       context->buffer->len = aligned_len;
     }
 }
Index: /home/stefan/develop/performance/subversion/libsvn_subr/cache-membuffer.c
===================================================================
--- /home/stefan/develop/performance/subversion/libsvn_subr/cache-membuffer.c (revision 990600)
+++ /home/stefan/develop/performance/subversion/libsvn_subr/cache-membuffer.c (working copy)
@@ -110,6 +110,10 @@
    */
   unsigned char key [KEY_SIZE];
 
+ /* TODO remove this debug item.
+ */
+ unsigned char checksum [KEY_SIZE];
+
   /* If -1, the entry is not in used. Otherwise, it is the offset of the
    * cached item's serialized data within the data buffer.
    */
@@ -809,6 +813,7 @@
                     apr_size_t key_len,
                     void *item,
                     svn_cache__serialize_func_t serializer,
+ svn_cache__deserialize_func_t deserializer,
                     apr_pool_t *pool)
 {
   apr_uint32_t group_index;
@@ -817,6 +822,9 @@
   char *buffer;
   apr_size_t size;
 
+ /* TODO remove this debug code */
+ svn_checksum_t *checksum;
+
   /* find the entry group that will hold the key.
    */
   group_index = get_group_index(cache, key, key_len, to_find, pool);
@@ -827,6 +835,25 @@
    */
   SVN_ERR(serializer(&buffer, &size, item, pool));
 
+ /* TODO remove this debug code */
+ if (deserializer)
+ {
+ char *buffer2;
+ apr_size_t size2;
+
+ /* deserialization must work */
+ void *item2 = apr_palloc(pool, size);
+ memcpy(item2, buffer, size);
+ SVN_ERR(deserializer(&item2, item2, size, pool));
+
+ /* second serialization must yield the same result as the first one */
+ SVN_ERR(serializer(&buffer2, &size2, item2, pool));
+ assert(size == size2 && !memcmp(buffer, buffer2, size));
+ }
+ {
+ SVN_ERR(svn_checksum(&checksum, svn_checksum_md5, buffer, size, pool));
+ }
+
   /* The actual cache data access needs to sync'ed
    */
   SVN_ERR(lock_cache(cache));
@@ -843,6 +870,11 @@
       entry->size = size;
       entry->offset = cache->current_data;
 
+ /* TODO remove this debug code */
+ {
+ memcpy(entry->checksum, checksum->digest, APR_MD5_DIGESTSIZE);
+ }
+
       /* Copy the serialized item data into the cache.
        */
       if (size)
@@ -914,6 +946,13 @@
                ((apr_size_t)apr_palloc(pool, size + ITEM_ALIGNMENT-1));
   memcpy(buffer, (const char*)cache->data + entry->offset, size);
 
+ /* TODO remove this debug code */
+ {
+ svn_checksum_t *checksum;
+ SVN_ERR(svn_checksum(&checksum, svn_checksum_md5, buffer, entry->size, pool));
+ assert(!memcmp(entry->checksum, checksum->digest, APR_MD5_DIGESTSIZE));
+ }
+
   /* update hit statistics
    */
   entry->hit_count++;
@@ -1099,6 +1138,39 @@
   return SVN_NO_ERROR;
 }
 
+/* standard serialization function for svn_stringbuf_t items
+ */
+static svn_error_t *
+serialize_svn_stringbuf(char **buffer,
+ apr_size_t *buffer_size,
+ void *item,
+ apr_pool_t *pool)
+{
+ svn_stringbuf_t *value_str = item;
+
+ *buffer = value_str->data;
+ *buffer_size = value_str->len + 1;
+
+ return SVN_NO_ERROR;
+}
+
+/* standard de-serialization function for svn_stringbuf_t items
+ */
+static svn_error_t *
+deserialize_svn_stringbuf(void **item,
+ const char *buffer,
+ apr_size_t buffer_size,
+ apr_pool_t *pool)
+{
+ svn_string_t *value_str = apr_palloc(pool, sizeof(svn_string_t));
+
+ value_str->data = (char*)buffer;
+ value_str->len = buffer_size-1;
+ *item = value_str;
+
+ return SVN_NO_ERROR;
+}
+
 /* Implement svn_cache__vtable_t.set
  */
 static svn_error_t *
@@ -1141,6 +1213,9 @@
                              full_key_len,
                              value,
                              cache->serializer,
+ cache->deserializer == deserialize_svn_stringbuf
+ ? NULL
+ : cache->deserializer,
                              cache->pool);
 }
 
@@ -1212,39 +1287,6 @@
   svn_membuffer_cache_is_cachable
 };
 
-/* standard serialization function for svn_stringbuf_t items
- */
-static svn_error_t *
-serialize_svn_stringbuf(char **buffer,
- apr_size_t *buffer_size,
- void *item,
- apr_pool_t *pool)
-{
- svn_stringbuf_t *value_str = item;
-
- *buffer = value_str->data;
- *buffer_size = value_str->len + 1;
-
- return SVN_NO_ERROR;
-}
-
-/* standard de-serialization function for svn_stringbuf_t items
- */
-static svn_error_t *
-deserialize_svn_stringbuf(void **item,
- const char *buffer,
- apr_size_t buffer_size,
- apr_pool_t *pool)
-{
- svn_string_t *value_str = apr_palloc(pool, sizeof(svn_string_t));
-
- value_str->data = (char*)buffer;
- value_str->len = buffer_size-1;
- *item = value_str;
-
- return SVN_NO_ERROR;
-}
-
 /* Construct a svn_cache__t object on top of a shared memcache.
  */
 svn_error_t *
Index: /home/stefan/develop/performance/subversion/libsvn_fs_fs/dag.c
===================================================================
--- /home/stefan/develop/performance/subversion/libsvn_fs_fs/dag.c (revision 990572)
+++ /home/stefan/develop/performance/subversion/libsvn_fs_fs/dag.c (working copy)
@@ -1102,6 +1102,10 @@
     svn_temp_serializer__set_null(context,
                                   (const void * const *)&node->node_revision);
 
+ /* TODO remove this debug code */
+ svn_temp_serializer__set_null(context,
+ (const void * const *)&node->fs);
+
   /* serialize other sub-structures */
   svn_fs_fs__id_serialize(context, (const svn_fs_id_t **)&node->id);
   svn_fs_fs__id_serialize(context, &node->fresh_root_predecessor_id);