Register Guidelines E-Books Search Today's Posts Mark Forums Read

Go Back   MobileRead Forums > E-Book Software > Calibre

Notices

Reply
 
Thread Tools Search this Thread
Old 09-18-2018, 12:54 AM   #1
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
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.
JimmXinu is offline   Reply With Quote
Old 09-18-2018, 05:43 AM   #2
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
Join Date: Oct 2006
Location: Mumbai, India
Device: Various
run calibre in debug mode too see exactly what is taking so long
kovidgoyal is offline   Reply With Quote
Advert
Old 09-18-2018, 10:38 AM   #3
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
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.
Attached Files
File Type: txt new-kindle.txt (6.9 KB, 12 views)
File Type: txt old-kindle.txt (7.7 KB, 13 views)

Last edited by JimmXinu; 09-18-2018 at 10:38 AM. Reason: correct spelling
JimmXinu is offline   Reply With Quote
Old 09-18-2018, 11:16 AM   #4
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
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
kovidgoyal is offline   Reply With Quote
Old 09-18-2018, 12:49 PM   #5
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
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:

I got a popup telling me there was an error and no GUI:
Code:
ERROR: Startup error: There was an error during calibre startup. Parts of calibre may not function. Click Show details to learn more.

Traceback (most recent call last):
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\gui2\main.py", line 289, in initialize_db_stage2
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\gui2\main.py", line 233, in start_gui
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\gui2\ui.py", line 247, in initialize
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\gui2\layout.py", line 332, in init_main_window_mixin
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\gui2\actions\fetch_news.py", line 32, in init_scheduler
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\gui2\dialogs\scheduler.py", line 586, in __init__
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\web\feeds\recipes\model.py", line 157, in __init__
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\web\feeds\recipes\model.py", line 226, in do_refresh
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\web\feeds\recipes\model.py", line 218, in factory
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\web\feeds\recipes\model.py", line 66, in __init__
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\utils\localization.py", line 379, in get_language
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\utils\localization.py", line 359, in get_iso_language
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\utils\localization.py", line 352, in _load_iso639
  File "C:\Users\jimm\Desktop\nook\calibre\src\calibre\utils\resources.py", line 75, in get_path
IOError: [Errno 2] No such file or directory: 'C:\\Users\\jimm\\Desktop\\nook\\calibre\\resources\\localization\\iso639.calibre_msgpack'


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

def do_cprofile(func):
    def profiled_func(*args, **kwargs):
        profile = cProfile.Profile()
        try:
            profile.enable()
            result = func(*args, **kwargs)
            profile.disable()
            return result
        finally:
            profile.print_stats()
    return profiled_func
...
    @do_cprofile
    def sync_booklists(self, booklists, end_session=True):
        debug_print('USBMS: starting sync_booklists')
...


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.
JimmXinu is offline   Reply With Quote
Advert
Old 09-18-2018, 12:55 PM   #6
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
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.
kovidgoyal is offline   Reply With Quote
Old 09-18-2018, 12:59 PM   #7
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
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.
kovidgoyal is offline   Reply With Quote
Old 09-18-2018, 01:00 PM   #8
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
Join Date: Oct 2006
Location: Mumbai, India
Device: Various
Quote:
Originally Posted by kovidgoyal View Post
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.
kovidgoyal is offline   Reply With Quote
Old 09-18-2018, 01:19 PM   #9
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
Quote:
Originally Posted by kovidgoyal View Post
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 is offline   Reply With Quote
Old 09-18-2018, 02:36 PM   #10
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
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 is offline   Reply With Quote
Old 09-18-2018, 09:46 PM   #11
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
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.
JimmXinu is offline   Reply With Quote
Old 09-19-2018, 12:03 AM   #12
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
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.
kovidgoyal is offline   Reply With Quote
Old 09-19-2018, 12:39 AM   #13
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
Quote:
Originally Posted by kovidgoyal View Post
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 View Post
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.
JimmXinu is offline   Reply With Quote
Old 09-19-2018, 01:05 AM   #14
kovidgoyal
creator of calibre
kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.kovidgoyal ought to be getting tired of karma fortunes by now.
 
kovidgoyal's Avatar
 
Posts: 33,747
Karma: 10215946
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
kovidgoyal is offline   Reply With Quote
Old 09-19-2018, 01:11 PM   #15
JimmXinu
Plugin Developer
JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.JimmXinu ought to be getting tired of karma fortunes by now.
 
JimmXinu's Avatar
 
Posts: 3,482
Karma: 589322
Join Date: Dec 2011
Location: Midwest USA
Device: Kindle Voyage
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.
JimmXinu is offline   Reply With Quote
Reply

Thread Tools Search this Thread
Search this Thread:

Advanced Search

Forum Jump

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


All times are GMT -4. The time now is 04:11 PM.


MobileRead.com is a privately owned, operated and funded community.