Send metadata to device Slow on 2nd Kindle Voyage?

JimmXinu · 09-17-2018, 11:54 PM

I have a three year old Kindle Voyage that I love. A 'Send metadata to device' job after updating a few books on it takes 15-30 seconds.

I just bought a 2nd Kindle Voyage(new from Amazon) for a backup (it looks like Amazon is dropping Voyage). A 'Send metadata to device' job after updating a few books on the new one takes 3-5 minutes.

This is after the background book indexing has finished for the books already loaded--that took a few days.

I recall that something changed in Calibre a while back that vastly improved 'Send metadata to device' time. Is there some setting I have forgotten? Or some other hint why it's so much slower?

Thanks.

kovidgoyal · 09-18-2018, 04:43 AM

run calibre in debug mode too see exactly what is taking so long

JimmXinu · 09-18-2018, 09:38 AM

Here's a debug log from each showing a small update.

Aside from some re-ordering and old Kindle getting 2 books vs 1 for new Kindle, I don't see anything in the logs. But hopefully you can. See attached.

kovidgoyal · 09-18-2018, 10:16 AM

Nothing jumps out at me. Try adding some more debugs into the sync_booklists() function in usbms/driver.py and see where inside that unction it is taking long. If I had to guess I would choose lines 445-447

JimmXinu · 09-18-2018, 11:49 AM

I was unable to run using CALIBRE_DEVELOP_FROM pointing to the current GitHub master. Unrelated to the issue I'm having, but thought you'd want to know. Details:

Spoiler:

Going back to the v3.31.0 tag worked. I turned on cProfile around sync_booklists:

Spoiler:

Results with new Kindle:

Spoiler:

Code:

DEBUG:   81.1 USBMS: starting sync_booklists
Job: 4 Upload one book to the device: Chimaera finished
No details available.
DEBUG:  345.5 USBMS: finished sync_booklists
         64872424 function calls (49010574 primitive calls) in 264.343 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.000    0.000    0.000    0.000 Queue.py:107(put)
        2    0.000    0.000    0.000    0.000 Queue.py:204(_put)
        2    0.000    0.000    0.000    0.000 __init__.py:178(prints)
        1    0.086    0.086    7.213    7.213 __init__.py:193(dumps)
   396501    0.095    0.000    0.156    0.000 __init__.py:640(isbytestring)
        1    0.000    0.000    0.030    0.030 __init__.py:720(fsync)
        1    0.000    0.000    0.000    0.000 _abcoll.py:548(update)
        1    0.000    0.000    0.000    0.000 _weakrefset.py:70(__contains__)
        1    0.000    0.000    0.000    0.000 abc.py:148(__subclasscheck__)
   473569    0.288    0.000    0.319    0.000 base.py:124(__getattribute__)
     5321    0.026    0.000    0.031    0.000 base.py:161(__setattr__)
   154309    0.074    0.000    0.268    0.000 base.py:213(get)
     5321    0.105    0.000    6.179    0.001 base.py:360(get_all_user_metadata)
     5318    0.457    0.000    1.145    0.000 base64.py:43(b64encode)
        1    0.000    0.000    0.000    0.000 collections.py:50(__init__)
       26    0.000    0.000    0.000    0.000 collections.py:71(__setitem__)
2742536/58498    2.833    0.000    6.074    0.000 copy.py:145(deepcopy)
  2261447    0.167    0.000    0.167    0.000 copy.py:198(_deepcopy_atomic)
    63816    0.064    0.000    0.180    0.000 copy.py:226(_deepcopy_list)
10076/5038    0.042    0.000    0.212    0.000 copy.py:234(_deepcopy_tuple)
233702/58498    0.887    0.000    5.952    0.000 copy.py:253(_deepcopy_dict)
  2579117    1.061    0.000    1.403    0.000 copy.py:267(_keep_alive)
10076/5038    0.035    0.000    0.239    0.000 copy.py:306(_reconstruct)
     5038    0.003    0.000    0.005    0.000 copy_reg.py:92(__newobj__)
        1    0.000    0.000    0.000    0.000 cp1252.py:14(decode)
    20974    0.037    0.000    0.117    0.000 date.py:187(isoformat)
        1    0.000    0.000    0.000    0.000 device.py:80(report_progress)
        2    0.000    0.000    0.000    0.000 driver.py:40(debug_print)
        1    0.003    0.003  264.343  264.343 driver.py:446(sync_booklists)
        3    0.008    0.003  264.308   88.103 driver.py:454(write_prefix)
        2    0.000    0.000    0.000    0.000 driver.py:481(path_to_unicode)
        2    0.000    0.000    0.000    0.000 driver.py:487(normalize_path)
        1    0.000    0.000    0.000    0.000 encoder.py:101(__init__)
        1    0.610    0.610    7.127    7.127 encoder.py:186(encode)
        1    0.000    0.000    0.000    0.000 encoder.py:212(iterencode)
     1067    0.001    0.000    0.002    0.000 encoder.py:236(floatstr)
        1    0.000    0.000    0.000    0.000 encoder.py:272(_make_iterencode)
7018795/6653880    1.009    0.000    5.599    0.000 encoder.py:288(_iterencode_list)
19207551/6653877    3.575    0.000    4.802    0.000 encoder.py:341(_iterencode_dict)
  6653880    0.780    0.000    6.379    0.000 encoder.py:417(_iterencode)
        1    0.000    0.000    0.000    0.000 field_metadata.py:30(_builtin_field_metadata)
        1    0.000    0.000    0.000    0.000 field_metadata.py:386(__init__)
    95778    0.032    0.000    0.032    0.000 field_metadata.py:409(__getitem__)
   154309    0.046    0.000    0.046    0.000 field_metadata.py:424(__contains__)
       26    0.000    0.000    0.000    0.000 field_metadata.py:660(_add_search_terms_to_map)
        2    0.000    0.000    0.000    0.000 genericpath.py:23(exists)
       21    0.000    0.000    0.000    0.000 gettext.py:219(ugettext)
        1    0.000    0.000    0.000    0.000 gettext.py:224(ungettext)
        1    0.000    0.000    0.000    0.000 json_codec.py:129(__init__)
        1    0.226    0.226  262.665  262.665 json_codec.py:132(encode_to_file)
        1    0.006    0.006    8.968    8.968 json_codec.py:136(encode_booklist_metadata)
     5321    0.067    0.000    8.960    0.002 json_codec.py:142(encode_book_metadata)
   159630    0.349    0.000    8.893    0.000 json_codec.py:148(encode_metadata_attr)
    21281    0.109    0.000    0.233    0.000 json_codec.py:30(datetime_to_string)
     5321    0.026    0.000    1.172    0.000 json_codec.py:43(encode_thumbnail)
206968/133025    0.206    0.000    0.370    0.000 json_codec.py:70(object_to_unicode)
        1    0.000    0.000    0.000    0.000 json_codec.py:72(dec)
    58498    0.042    0.000    0.056    0.000 json_codec.py:89(encode_is_multiple)
        2    0.000    0.000    0.000    0.000 mbcs.py:20(decode)
        1    0.000    0.000    0.000    0.000 ntpath.py:63(join)
        2    0.000    0.000    0.000    0.000 ntpath.py:96(splitdrive)
        2    0.000    0.000    0.000    0.000 os.py:444(__contains__)
        1    0.000    0.000    1.605    1.605 startup.py:114(local_open)
        2    0.000    0.000    0.000    0.000 threading.py:300(_is_owned)
        2    0.000    0.000    0.000    0.000 threading.py:373(notify)
    41138    0.005    0.000    0.005    0.000 tz.py:33(utcoffset)
    10082    0.001    0.000    0.001    0.000 tz.py:36(dst)
        1    0.000    0.000    0.000    0.000 {_codecs.charmap_decode}
        2    0.000    0.000    0.000    0.000 {_codecs.mbcs_decode}
  2299871    0.426    0.000    0.426    0.000 {_json.encode_basestring_ascii}
     5318    0.688    0.000    0.688    0.000 {binascii.b2a_base64}
     5038    0.002    0.000    0.002    0.000 {built-in method __new__ of type object at 0x000000006C515330}
    20152    0.019    0.000    0.019    0.000 {getattr}
    46986    0.012    0.000    0.012    0.000 {hasattr}
  5926181    0.319    0.000    0.319    0.000 {id}
  5294237    0.688    0.000    0.688    0.000 {isinstance}
    10076    0.003    0.000    0.003    0.000 {issubclass}
    20169    0.002    0.000    0.002    0.000 {len}
    10076    0.048    0.000    0.048    0.000 {method '__reduce_ex__' of 'object' objects}
        4    0.000    0.000    0.000    0.000 {method 'acquire' of 'thread.lock' objects}
        2    0.000    0.000    0.000    0.000 {method 'append' of 'collections.deque' objects}
  2599700    0.212    0.000    0.212    0.000 {method 'append' of 'list' objects}
    20974    0.013    0.000    0.015    0.000 {method 'astimezone' of 'datetime.datetime' objects}
        3    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'fileno' of 'file' objects}
        1    0.004    0.004    0.004    0.004 {method 'flush' of 'file' objects}
  5555180    0.399    0.000    0.399    0.000 {method 'get' of 'dict' objects}
    20974    0.060    0.000    0.063    0.000 {method 'isoformat' of 'datetime.datetime' objects}
    21285    0.009    0.000    0.009    0.000 {method 'items' of 'dict' objects}
   382483    0.033    0.000    0.033    0.000 {method 'iteritems' of 'dict' objects}
     5321    0.000    0.000    0.000    0.000 {method 'iterkeys' of 'dict' objects}
     5321    0.001    0.000    0.001    0.000 {method 'itervalues' of 'dict' objects}
        1    0.139    0.139    0.139    0.139 {method 'join' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'release' of 'thread.lock' objects}
        4    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
     5038    0.002    0.000    0.002    0.000 {method 'update' of 'dict' objects}
        2    0.000    0.000    0.000    0.000 {method 'upper' of 'str' objects}
        9  246.259   27.362  246.259   27.362 {method 'write' of 'file' objects}
        1    0.026    0.026    0.026    0.026 {nt.fsync}
        2    0.000    0.000    0.000    0.000 {nt.stat}
        1    1.605    1.605    1.605    1.605 {open}
    10076    0.007    0.000    0.007    0.000 {range}
     1067    0.001    0.000    0.001    0.000 {repr}
        2    0.000    0.000    0.000    0.000 {time.time}


DeviceJob: 5 Send metadata to device done, calling callback
DeviceJob: 5 Send metadata to device callback returned
Job: 5 Send metadata to device finished
No details available.

It looks like the lion's share of the time is in method 'write' of 'file' objects.

By contrast, here's the same for the old Kindle:

Spoiler:

Code:

DEBUG: 1358.7 USBMS: starting sync_booklists
Job: 11 Upload one book to the device: Chimaera finished
No details available.
DEBUG: 1370.9 USBMS: finished sync_booklists
         8534666 function calls (7605838 primitive calls) in 12.186 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.000    0.000    0.000    0.000 Queue.py:107(put)
        2    0.000    0.000    0.000    0.000 Queue.py:204(_put)
        2    0.000    0.000    0.000    0.000 __init__.py:178(prints)
        1    0.032    0.032    1.081    1.081 __init__.py:193(dumps)
   375708    0.077    0.000    0.130    0.000 __init__.py:640(isbytestring)
        1    0.000    0.000    0.140    0.140 __init__.py:720(fsync)
        1    0.000    0.000    0.000    0.000 _abcoll.py:548(update)
        1    0.000    0.000    0.000    0.000 _weakrefset.py:70(__contains__)
        1    0.000    0.000    0.000    0.000 abc.py:148(__subclasscheck__)
   473480    0.250    0.000    0.282    0.000 base.py:124(__getattribute__)
     5320    0.013    0.000    0.019    0.000 base.py:161(__setattr__)
   154280    0.068    0.000    0.249    0.000 base.py:213(get)
     5320    0.012    0.000    0.288    0.000 base.py:360(get_all_user_metadata)
      238    0.045    0.000    0.101    0.000 base64.py:43(b64encode)
        1    0.000    0.000    0.000    0.000 collections.py:50(__init__)
       26    0.000    0.000    0.000    0.000 collections.py:71(__setitem__)
123215/2618    0.126    0.000    0.276    0.000 copy.py:145(deepcopy)
   101830    0.007    0.000    0.007    0.000 copy.py:198(_deepcopy_atomic)
     2856    0.004    0.000    0.010    0.000 copy.py:226(_deepcopy_list)
  462/231    0.002    0.000    0.010    0.000 copy.py:234(_deepcopy_tuple)
10455/2618    0.041    0.000    0.270    0.000 copy.py:253(_deepcopy_dict)
   116065    0.048    0.000    0.064    0.000 copy.py:267(_keep_alive)
  462/231    0.002    0.000    0.011    0.000 copy.py:306(_reconstruct)
      231    0.000    0.000    0.000    0.000 copy_reg.py:92(__newobj__)
        1    0.000    0.000    0.000    0.000 cp1252.py:14(decode)
     6005    0.010    0.000    0.030    0.000 date.py:187(isoformat)
        1    0.000    0.000    0.000    0.000 device.py:80(report_progress)
        2    0.000    0.000    0.000    0.000 driver.py:40(debug_print)
        1    0.003    0.003   12.186   12.186 driver.py:446(sync_booklists)
        3    0.018    0.006   12.164    4.055 driver.py:454(write_prefix)
        2    0.000    0.000    0.000    0.000 driver.py:481(path_to_unicode)
        2    0.000    0.000    0.000    0.000 driver.py:487(normalize_path)
        1    0.000    0.000    0.000    0.000 encoder.py:101(__init__)
        1    0.104    0.104    1.049    1.049 encoder.py:186(encode)
        1    0.000    0.000    0.000    0.000 encoder.py:212(iterencode)
       30    0.000    0.000    0.000    0.000 encoder.py:236(floatstr)
        1    0.000    0.000    0.000    0.000 encoder.py:272(_make_iterencode)
1115953/1014151    0.218    0.000    0.802    0.000 encoder.py:288(_iterencode_list)
1659392/1014148    0.358    0.000    0.668    0.000 encoder.py:341(_iterencode_dict)
  1014151    0.120    0.000    0.923    0.000 encoder.py:417(_iterencode)
        1    0.000    0.000    0.000    0.000 field_metadata.py:30(_builtin_field_metadata)
        1    0.000    0.000    0.000    0.000 field_metadata.py:386(__init__)
    95760    0.026    0.000    0.026    0.000 field_metadata.py:409(__getitem__)
   154280    0.039    0.000    0.039    0.000 field_metadata.py:424(__contains__)
       26    0.000    0.000    0.000    0.000 field_metadata.py:660(_add_search_terms_to_map)
        2    0.000    0.000    0.000    0.000 genericpath.py:23(exists)
       21    0.000    0.000    0.000    0.000 gettext.py:219(ugettext)
        1    0.000    0.000    0.000    0.000 gettext.py:224(ungettext)
        3    0.000    0.000    0.000    0.000 iso8601.py:19(_isdst)
        1    0.000    0.000    0.000    0.000 json_codec.py:129(__init__)
        1    0.038    0.038   11.346   11.346 json_codec.py:132(encode_to_file)
        1    0.004    0.004    1.631    1.631 json_codec.py:136(encode_booklist_metadata)
     5320    0.086    0.000    1.625    0.000 json_codec.py:142(encode_book_metadata)
   159600    0.272    0.000    1.538    0.000 json_codec.py:148(encode_metadata_attr)
    16198    0.054    0.000    0.085    0.000 json_codec.py:30(datetime_to_string)
     5320    0.014    0.000    0.115    0.000 json_codec.py:43(encode_thumbnail)
185886/133000    0.171    0.000    0.309    0.000 json_codec.py:70(object_to_unicode)
        1    0.000    0.000    0.000    0.000 json_codec.py:72(dec)
     2618    0.002    0.000    0.003    0.000 json_codec.py:89(encode_is_multiple)
        2    0.000    0.000    0.000    0.000 mbcs.py:20(decode)
        1    0.000    0.000    0.000    0.000 ntpath.py:63(join)
        2    0.000    0.000    0.000    0.000 ntpath.py:96(splitdrive)
        2    0.000    0.000    0.000    0.000 os.py:444(__contains__)
        1    0.000    0.000    0.661    0.661 startup.py:114(local_open)
        2    0.000    0.000    0.000    0.000 threading.py:300(_is_owned)
        2    0.000    0.000    0.000    0.000 threading.py:373(notify)
        3    0.000    0.000    0.000    0.000 tz.py:114(_isdst)
     6940    0.001    0.000    0.001    0.000 tz.py:33(utcoffset)
      468    0.000    0.000    0.000    0.000 tz.py:36(dst)
        3    0.000    0.000    0.000    0.000 tz.py:95(utcoffset)
        1    0.000    0.000    0.000    0.000 {_codecs.charmap_decode}
        2    0.000    0.000    0.000    0.000 {_codecs.mbcs_decode}
   361686    0.129    0.000    0.129    0.000 {_json.encode_basestring_ascii}
      238    0.056    0.000    0.056    0.000 {binascii.b2a_base64}
      231    0.000    0.000    0.000    0.000 {built-in method __new__ of type object at 0x000000006C515330}
      924    0.001    0.000    0.001    0.000 {getattr}
    12241    0.002    0.000    0.002    0.000 {hasattr}
   291992    0.016    0.000    0.016    0.000 {id}
  1475865    0.204    0.000    0.204    0.000 {isinstance}
      462    0.000    0.000    0.000    0.000 {issubclass}
      941    0.000    0.000    0.000    0.000 {len}
      462    0.002    0.000    0.002    0.000 {method '__reduce_ex__' of 'object' objects}
        4    0.000    0.000    0.000    0.000 {method 'acquire' of 'thread.lock' objects}
        2    0.000    0.000    0.000    0.000 {method 'append' of 'collections.deque' objects}
   122547    0.013    0.000    0.013    0.000 {method 'append' of 'list' objects}
     6005    0.001    0.000    0.001    0.000 {method 'astimezone' of 'datetime.datetime' objects}
        3    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'fileno' of 'file' objects}
        1    0.002    0.002    0.002    0.002 {method 'flush' of 'file' objects}
   397124    0.049    0.000    0.049    0.000 {method 'get' of 'dict' objects}
     6005    0.017    0.000    0.018    0.000 {method 'isoformat' of 'datetime.datetime' objects}
    21281    0.006    0.000    0.006    0.000 {method 'items' of 'dict' objects}
    27280    0.004    0.000    0.004    0.000 {method 'iteritems' of 'dict' objects}
     5320    0.000    0.000    0.000    0.000 {method 'iterkeys' of 'dict' objects}
     5320    0.001    0.000    0.001    0.000 {method 'itervalues' of 'dict' objects}
        1    0.023    0.023    0.023    0.023 {method 'join' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'release' of 'thread.lock' objects}
        4    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        3    0.000    0.000    0.000    0.000 {method 'toordinal' of 'datetime.date' objects}
      231    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}
        2    0.000    0.000    0.000    0.000 {method 'upper' of 'str' objects}
        9    8.595    0.955    8.595    0.955 {method 'write' of 'file' objects}
        1    0.137    0.137    0.137    0.137 {nt.fsync}
        2    0.000    0.000    0.000    0.000 {nt.stat}
        1    0.661    0.661    0.661    0.661 {open}
      462    0.000    0.000    0.000    0.000 {range}
       30    0.000    0.000    0.000    0.000 {repr}
        3    0.000    0.000    0.000    0.000 {time.localtime}
        2    0.000    0.000    0.000    0.000 {time.time}


DeviceJob: 12 Send metadata to device done, calling callback
DeviceJob: 12 Send metadata to device callback returned
Job: 12 Send metadata to device finished

The number of writes is the same (only 9), but the time length is radically different.

It does not look like it's the same processing between the two. For example method 'get' of 'dict' objects is called ~400k times on the old Kindle and 5.5m times on the new one.

kovidgoyal · 09-18-2018, 11:55 AM

Yeah currently running from master is broken, because of some ongoing py3 compat work. I should have told you that, sorry.

write being slow indicates device issues. It may be possible to work around it by changing the code to use a single write instead of mltiple ones. essentially change the json serialization to output a string whichis written to the file in one write call.

kovidgoyal · 09-18-2018, 11:59 AM

Oh and unless the metadata and books on the two kindles are identical, the various other calls will be expected to be different.

kovidgoyal · 09-18-2018, 12:00 PM

Quote:

Originally Posted by kovidgoyal

It may be possible to work around it by changing the code to use a single write instead of mltiple ones. essentially change the json serialization to output a string whichis written to the file in one write call.

Sorry scratch that, I took a look at the code and it is already doing that. Dont have any more (not very) bright ideas.

JimmXinu · 09-18-2018, 12:19 PM

Quote:

Originally Posted by kovidgoyal

Oh and unless the metadata and books on the two kindles are identical, the various other calls will be expected to be different.

I've made an effort to try and make them the same. I can't say that they were all loaded in the same order, but they do contain the same books from the same library--and therefore the same metadata I assume.

Or so I thought. metadata.calibre is 16M on the old Kindle and 180M on the new one. Which would explain the difference in write time. Guess I should have checked that first.

Now the question is: Why are the metadata.calibre file sizes so different with the same ebooks from the same library?

JimmXinu · 09-18-2018, 01:36 PM

Examining the contents of the metadata.calibre files, I find that the new one has complete user_metadata and thumbnail for all ebooks from the library.

The old device file has those for some ebooks (newer ones) but they are null / {} for most.

The contents of the user_metadata and thumbnail elements make up ~95% of the 178M metadata.calibre file on the new device. Removing them brings it down to roughly the same size.

Since the old device doesn't have values for these, clearly they aren't necessary for Kindle. Is there a tweak or option somewhere I could use to not send them to the device?

And if not, would you object to having such a tweak or option?

JimmXinu · 09-18-2018, 08:46 PM

FYI, I've made a github PR for this that is working for me.

Requires a change to Tweaks so it doesn't effect anyone who doesn't specifically set it, but for me, it reduces time to send metadata from 5 minutes to <10 seconds.

kovidgoyal · 09-18-2018, 11:03 PM

The thumbnails are used in the device view in calibre. IIRC the user_metadata was added to support the wifi device connection/calibre companion use case.

I'm somewhat surprised that the old voyage does not have those data. All (reasonably modern) kindles share the same driver as far as I know. And all the kindle drivers delegate the creation of metadata.calibre to usbms/driver.py

I'd like to track down why the old voyage does not have that data available, if possible.

Rather than a tweak, it is probably better to allow individual device drivers to specify if they need user_metadata or not. Not to mention that a tweak could allow users to exclude arbitrary metadata which can lead to subtle and hard to diagnore bugs.

I'd rather not remove the thumbnails, since as I said they are used by calibre itself, for the covers in the device view.

JimmXinu · 09-18-2018, 11:39 PM

Quote:

Originally Posted by kovidgoyal

The thumbnails are used in the device view in calibre. IIRC the user_metadata was added to support the wifi device connection/calibre companion use case.

I'm somewhat surprised that the old voyage does not have those data. All (reasonably modern) kindles share the same driver as far as I know. And all the kindle drivers delegate the creation of metadata.calibre to usbms/driver.py

I'd like to track down why the old voyage does not have that data available, if possible.

I speculate that only books sent to the device more recently have thumbnails & user_metadata. More recently than what, I couldn't say off hand.

But I can tell you that out of a library of ~5300 with daily updates, only 238 have thumbnails & user_metadata. That's about a month worth of updates.

Quote:

Originally Posted by kovidgoyal

Rather than a tweak, it is probably better to allow individual device drivers to specify if they need user_metadata or not. Not to mention that a tweak could allow users to exclude arbitrary metadata which can lead to subtle and hard to diagnore bugs.

I'd rather not remove the thumbnails, since as I said they are used by calibre itself, for the covers in the device view.

Do you have a different suggestion you would accept?

Because I consider a savings of 5 minutes (frequently several times a day) and ~170M of device storage more than worth giving up thumbnails on device and some redundant metadata.

kovidgoyal · 09-19-2018, 12:05 AM

There definitely haven't been any (intentional) changes to sending thumbnails in the last month.

What is the breakup of the data in thumbnails vs user metadata? user_metatata I am willing to get rid of on a per device basis.

Thumbnails can be fixed in one of several ways:

1) Stop storing them in metadata.calibre and instead use a subdirectory named calibre-thumbnails or similar. That way update jobs dont have to resend all thumbnails on every update.

2) Make it a per device driver thing. For instance e-ink kindles have calibre send thumbnails as separate files already. the driver could be changed to use those and not store thumbnails in metadata.calibre

JimmXinu · 09-19-2018, 12:11 PM

Of ~178M, ~118M thumbnails, ~50M user_metadata and ~7M everything else. (No, it doesn't add up--FAT32 size differences.)

Kindle Voyage is an e-ink kindle--unless that means something else specifically. If there are thumbnails as separate files, I don't see them. Plus, writing them as separate files helps with write time, but makes storage worse.

Due to the fact that calibre reads metadata.calibre, updates only changed books and then writes it again, simply removing thumbnails and user_metadata from my metadata.calibre when it gets too slow is a viable 'solution'. Apparently I've already been using that for months, because I'm sure it was longer ago than that it sped up for me.

09-17-2018, 11:54 PM	#1
JimmXinu Plugin Developer Posts: 6,307 Karma: 3966249 Join Date: Dec 2011 Location: Midwest USA Device: Kindle Paperwhite(10th)	Send metadata to device Slow on 2nd Kindle Voyage? I have a three year old Kindle Voyage that I love. A 'Send metadata to device' job after updating a few books on it takes 15-30 seconds. I just bought a 2nd Kindle Voyage(new from Amazon) for a backup (it looks like Amazon is dropping Voyage). A 'Send metadata to device' job after updating a few books on the new one takes 3-5 minutes. This is after the background book indexing has finished for the books already loaded--that took a few days. I recall that something changed in Calibre a while back that vastly improved 'Send metadata to device' time. Is there some setting I have forgotten? Or some other hint why it's so much slower? Thanks.

Similar Threads
Thread	Thread Starter	Forum	Replies	Last Post
Determine what metadata to send to device	sun_reads	Devices	0	10-03-2017 01:56 PM
Kindle Voyage metadata transfer very slow	HarryT	Devices	6	11-08-2014 12:36 PM
Send to device based on Metadata	DavidTC	Calibre	0	09-18-2011 01:18 PM
send book to device too much slow	danizzz	Calibre	0	06-23-2010 07:38 AM
Send to Device & Metadata	Bob Butler	Calibre	18	02-22-2009 09:33 PM

09-18-2018, 04:43 AM	#2
kovidgoyal creator of calibre Posts: 43,843 Karma: 22666666 Join Date: Oct 2006 Location: Mumbai, India Device: Various	run calibre in debug mode too see exactly what is taking so long

09-18-2018, 10:16 AM	#4
kovidgoyal creator of calibre Posts: 43,843 Karma: 22666666 Join Date: Oct 2006 Location: Mumbai, India Device: Various	Nothing jumps out at me. Try adding some more debugs into the sync_booklists() function in usbms/driver.py and see where inside that unction it is taking long. If I had to guess I would choose lines 445-447

09-18-2018, 11:55 AM	#6
kovidgoyal creator of calibre Posts: 43,843 Karma: 22666666 Join Date: Oct 2006 Location: Mumbai, India Device: Various	Yeah currently running from master is broken, because of some ongoing py3 compat work. I should have told you that, sorry. write being slow indicates device issues. It may be possible to work around it by changing the code to use a single write instead of mltiple ones. essentially change the json serialization to output a string whichis written to the file in one write call.

09-18-2018, 11:59 AM	#7
kovidgoyal creator of calibre Posts: 43,843 Karma: 22666666 Join Date: Oct 2006 Location: Mumbai, India Device: Various	Oh and unless the metadata and books on the two kindles are identical, the various other calls will be expected to be different.

09-18-2018, 01:36 PM	#10
JimmXinu Plugin Developer Posts: 6,307 Karma: 3966249 Join Date: Dec 2011 Location: Midwest USA Device: Kindle Paperwhite(10th)	Examining the contents of the metadata.calibre files, I find that the new one has complete user_metadata and thumbnail for all ebooks from the library. The old device file has those for some ebooks (newer ones) but they are null / {} for most. The contents of the user_metadata and thumbnail elements make up ~95% of the 178M metadata.calibre file on the new device. Removing them brings it down to roughly the same size. Since the old device doesn't have values for these, clearly they aren't necessary for Kindle. Is there a tweak or option somewhere I could use to not send them to the device? And if not, would you object to having such a tweak or option?

09-18-2018, 08:46 PM	#11
JimmXinu Plugin Developer Posts: 6,307 Karma: 3966249 Join Date: Dec 2011 Location: Midwest USA Device: Kindle Paperwhite(10th)	FYI, I've made a github PR for this that is working for me. Requires a change to Tweaks so it doesn't effect anyone who doesn't specifically set it, but for me, it reduces time to send metadata from 5 minutes to <10 seconds.

09-18-2018, 11:03 PM	#12
kovidgoyal creator of calibre Posts: 43,843 Karma: 22666666 Join Date: Oct 2006 Location: Mumbai, India Device: Various	The thumbnails are used in the device view in calibre. IIRC the user_metadata was added to support the wifi device connection/calibre companion use case. I'm somewhat surprised that the old voyage does not have those data. All (reasonably modern) kindles share the same driver as far as I know. And all the kindle drivers delegate the creation of metadata.calibre to usbms/driver.py I'd like to track down why the old voyage does not have that data available, if possible. Rather than a tweak, it is probably better to allow individual device drivers to specify if they need user_metadata or not. Not to mention that a tweak could allow users to exclude arbitrary metadata which can lead to subtle and hard to diagnore bugs. I'd rather not remove the thumbnails, since as I said they are used by calibre itself, for the covers in the device view.

09-19-2018, 12:05 AM	#14
kovidgoyal creator of calibre Posts: 43,843 Karma: 22666666 Join Date: Oct 2006 Location: Mumbai, India Device: Various	There definitely haven't been any (intentional) changes to sending thumbnails in the last month. What is the breakup of the data in thumbnails vs user metadata? user_metatata I am willing to get rid of on a per device basis. Thumbnails can be fixed in one of several ways: 1) Stop storing them in metadata.calibre and instead use a subdirectory named calibre-thumbnails or similar. That way update jobs dont have to resend all thumbnails on every update. 2) Make it a per device driver thing. For instance e-ink kindles have calibre send thumbnails as separate files already. the driver could be changed to use those and not store thumbnails in metadata.calibre

09-19-2018, 12:11 PM	#15
JimmXinu Plugin Developer Posts: 6,307 Karma: 3966249 Join Date: Dec 2011 Location: Midwest USA Device: Kindle Paperwhite(10th)	Of ~178M, ~118M thumbnails, ~50M user_metadata and ~7M everything else. (No, it doesn't add up--FAT32 size differences.) Kindle Voyage is an e-ink kindle--unless that means something else specifically. If there are thumbnails as separate files, I don't see them. Plus, writing them as separate files helps with write time, but makes storage worse. Due to the fact that calibre reads metadata.calibre, updates only changed books and then writes it again, simply removing thumbnails and user_metadata from my metadata.calibre when it gets too slow is a viable 'solution'. Apparently I've already been using that for months, because I'm sure it was longer ago than that it sped up for me.