Extra debug logs displaying requests duration

[Lucas-C]

Hi!

Today I tried to setup Calibre for my mother to use at home,
and it revealed to be very useful (good job!)
but also a bit frustrating on the search panel when the application fetch many websites,
and it takes ages to finish (we have a somehow slow connexion).

Hence quickly setup a dev environment (really easy to set up, good job again!) to try to figure out which online stores are slow to answer and should be disabled.

This resulted in this PR, that adds a bit of extra logging resulting in those lines:

While loading OpenSearch description, could not fetch URL http://assets0.feedbooks.net/opensearch.xml?t=1253087147
Overseer.fetch_url took 3.24s for URL https://www.amazon.com/s/?i=digital-text&k=georges+perec
Overseer.fetch_url took 8.23s for URL https://www.kobobooks.com/search/search.html?q=georges+perec
While loading OpenSearch description, could not fetch URL http://www.manybooks.net/opds/
Overseer.fetch_url took 9.65s for URL https://www.kobo.com/fr/en/ebook/the-art-and-craft-of-approaching-your-head-of-department-to-submit-a-request-for-a-raise
Overseer.fetch_url took 9.52s for URL https://www.kobo.com/fr/en/ebook/portrait-of-a-man-10
Overseer.fetch_url took 9.75s for URL https://www.kobo.com/fr/en/ebook/life-38
Overseer.fetch_url took 3.74s for URL https://www.kobo.com/fr/en/ebook/w-or-the-memory-of-childhood-by-georges-perec-book-analysis
Overseer.fetch_url took 4.37s for URL https://www.kobo.com/fr/en/ebook/georges-perec-a-life-in-words
Overseer.fetch_url took 4.75s for URL https://www.kobo.com/fr/en/ebook/georges-perec-is-my-hero
While loading OpenSearch description, could not fetch URL http://www.manybooks.net/opds/
While loading OpenSearch description, could not fetch URL http://assets0.feedbooks.net/opensearch.xml?t=1253087147
Overseer.fetch_url took 9.55s for URL https://www.kobobooks.com/search/search.html?q=georges+perec
Overseer.fetch_url took 5.44s for URL https://www.amazon.com/s/?i=digital-text&k=georges+perec
Overseer.fetch_url took 9.67s for URL https://www.kobo.com/fr/en/ebook/the-art-and-craft-of-approaching-your-head-of-department-to-submit-a-request-for-a-raise
Overseer.fetch_url took 9.86s for URL https://www.kobo.com/fr/en/ebook/portrait-of-a-man-10
Overseer.fetch_url took 9.88s for URL https://www.kobo.com/fr/en/ebook/i-remember-32
Overseer.fetch_url took 9.92s for URL https://www.kobo.com/fr/en/ebook/life-38
Overseer.fetch_url took 1.62s for URL https://www.kobo.com/fr/en/ebook/georges-perec-a-life-in-words
Overseer.fetch_url took 2.14s for URL https://www.kobo.com/fr/en/ebook/georges-perec-is-my-hero
Overseer.fetch_url took 2.78s for URL https://www.kobo.com/fr/en/ebook/the-hand-9
Overseer.fetch_url took 3.43s for URL https://www.kobo.com/fr/en/ebook/w-or-the-memory-of-childhood-by-georges-perec-book-analysis
Overseer.fetch_url took 2.40s for URL https://www.kobo.com/fr/en/ebook/diary-of-a-country-priest-2
Overseer.fetch_url took 5.07s for URL https://amazon.com/dp/B004ASOVSK
Overseer.fetch_url took 8.27s for URL https://amazon.com/dp/B085GMM4BK
Overseer.fetch_url took 13.14s for URL https://amazon.com/dp/B01A4APN84
Overseer.fetch_url took 8.85s for URL https://amazon.com/dp/B08T6JFSCJ
Overseer.fetch_url took 7.73s for URL https://amazon.com/dp/B0B9YNRNFH
Overseer.fetch_url took 14.65s for URL https://amazon.com/dp/B0711N6Y6C
Overseer.fetch_url took 5.33s for URL https://amazon.com/dp/B088FW2PDB
Overseer.fetch_url took 6.30s for URL https://amazon.com/dp/B00WNYBBTU
Overseer.fetch_url took 6.11s for URL https://amazon.com/dp/B081HJ5H8J
Overseer.fetch_url took 7.01s for URL https://amazon.com/dp/B00HRKONM2
Overseer.fetch_url took 5.64s for URL https://amazon.com/dp/B00SLVOLKU
Overseer.fetch_url took 5.45s for URL https://amazon.com/dp/B071P8C9HS
Overseer.fetch_url took 6.91s for URL https://amazon.com/dp/B010BEEWNU
Overseer.fetch_url took 6.83s for URL https://amazon.com/dp/B07F165YX3
Overseer.fetch_url took 6.19s for URL https://amazon.com/dp/B084YR8R66
Overseer.fetch_url took 7.07s for URL https://amazon.com/dp/B07147SK5W

I found it quite useful. Do you think this would make a nice addition to Calibre?

Regards

[kovidgoyal]

This is for the Get books feature?

[Lucas-C]

This is for the Get books feature?

Yes. This is what I meant when mentioning the "search panel" 😊

[kovidgoyal]

I am OK with outputting timing for get books fetches in principle, but having scraper/simple.py do it unconditionally based on DEBUG is not acceptable, as this could be used in different contexts in the future. Instead have it done in the get books code itself.

[Lucas-C]

I am OK with outputting timing for get books fetches in principle, but having scraper/simple.py do it unconditionally based on DEBUG is not acceptable, as this could be used in different contexts in the future. Instead have it done in the get books code itself.

OK, I have edited this PR in order to do so

As I have reduced the indentation in many code blocks,
the diff is better viewed when hiding whitespace changes: https://github.com/kovidgoyal/calibre/pull/1781/files?w=1

[kovidgoyal]

The store plugin code is live loaded, your PR would break Get Books for anybody not using up-to-date calibre. Also there seem to be a whole bunch of unrelated changes to logging. Logging how long a search takes for a given plugin should just be a five line patch, in the run method of the SearchThread class in download_thread.py

[Lucas-C]

Not very encouraging... 😔
I took the time to reduce a lot of redundant duplicated code in this PR, but that does not sound like a good thing.
Also, this is my first contribution to your project, I don't know about this plugin "live loading" mechanism. Where is it documented?

[kovidgoyal]

On Thu, Nov 03, 2022 at 12:50:57AM -0700, Lucas Cimon wrote: Not very encouraging... 😔 I took the time to reduce a lot of redundant duplicated code in this PR, but that does not sound like a good thing.

You are most welcome to do that, but separately from changing logging. And it would require some testing to make sure things didnt break.

Also, this is my first contribution to your project, I don't know about this plugin "live loading" mechanism. Where is it documented?

Almost all internet facing code in calibre is live loaded. Recipes, metadata download sources, get books stores, etc. So when you make changes to these they should generally be self contained, not depending on changes to other parts of calibre.