Heavy disc load

kermithermos · #1 (**permalink**) June 5th, 2023

Hi,

compaired to other file sharing clients phex produces a lot of disc access even if there are only a few donwloads with slow connection (>10kb/s).

It looks like internal buffers are flushed too often. Log is filled with:

Code:

[DownloadDataWriter] DEBUG phex.download.DownloadDataWriter - Trigger buffer write for phex.download.swarming.SWDownloadFile@abcdef, amount: 0

There a few entries with amount > 0 but the values are small but disc load of hdd sound like it writes hundreds of MB every few second. Whats going on here?

How can I reduce disc load? Increase Buffersize in phex.io.BufferSize.java and the classe which use these entries of BuferSize.java (MangagedFile, MemoryFile,...)?

GregorK · #2 (**permalink**) June 6th, 2023

If I remember correctly the configuration values to tune are:
Download.MaxWriteBufferPerDownload = 262144
Download.MaxTotalDownloadWriteBuffer = 1048576

Values are in bytes. Defaults are 256K and 1MB

You should be able to set them in phexCorePrefs.properties.
Check phex.prefs.core.DownloadPrefs for documentation of the values.

kermithermos · #3 (**permalink**) June 6th, 2023

Thank you.

kermithermos · #4 (**permalink**) June 6th, 2023

Hmm I increased both values:
Download.MaxTotalDownloadWriteBuffer=41943040
Download.MaxWriteBufferPerDownload=10485760

Still writes are initated every few seconds, buffers can never be filled in this short time if I have nearly no download traffic (< 1kb/s)

Log for DownloadDataWriter:

Code:

/foo/bar/phex_3.4.2.116$ ./startphex.sh
openjdk version "1.8.0_372"
OpenJDK Runtime Environment (build 1.8.0_372-b07)
...logback debug stuff ..

Jun 06, 2023 3:35:42 PM org.teleal.cling.UpnpServiceImpl <init>
INFORMATION: >>> Starting UPnP service...
...
INFORMATION: <<< UPnP service started successfully
230606 15:35:42.676(T0)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:35:47.683(T5007)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:35:47.684(T5008)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Time for complete write cycle.
230606 15:35:47.684(T5008)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@1dd46656, amount: 0
...
all are "amout : 0" here
...
230606 15:35:47.688(T5012)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6feba602, amount: 0
230606 15:35:47.689(T5013)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6ece4c0, amount: 1064960
230606 15:36:14.301(T31625)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@60b07181, amount: 0
...
all are "amout : 0" here
...
230606 15:36:14.328(T31652)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@4ea31d8b, amount: 0
230606 15:36:14.329(T31653)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7cc0aa5, amount: 0
230606 15:36:14.329(T31653)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3602dd16, amount: 298853
230606 15:36:20.644(T37968)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3690868a, amount: 284068
230606 15:36:26.796(T44120)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:36:41.188(T58512)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 2318039
230606 15:36:41.188(T58512)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:36:46.188(T63512)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:36:46.189(T63513)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3602dd16, amount: 109983
230606 15:36:49.096(T66420)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3690868a, amount: 284068
230606 15:36:55.325(T72649)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:37:09.447(T86771)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 2129169
230606 15:37:09.447(T86771)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:37:14.447(T91771)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:37:14.448(T91772)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3690868a, amount: 284068
230606 15:37:20.731(T98055)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:37:35.044(T112368)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 2019186
230606 15:37:35.044(T112368)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:37:40.044(T117368)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:37:40.045(T117369)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3690868a, amount: 284068
230606 15:37:46.954(T124278)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:38:00.914(T138238)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 2019186
230606 15:38:00.914(T138238)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:38:05.914(T143238)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:38:05.914(T143238)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Time for complete write cycle.
230606 15:38:05.914(T143238)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@1dd46656, amount: 0
230606 15:38:05.914(T143238)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6f1e4ccd, amount: 0
...
all are "amout : 0" here
...
230606 15:38:05.918(T143242)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7ab4d9c4, amount: 0
230606 15:38:05.918(T143242)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@61387304, amount: 1064960
230606 15:38:31.437(T168761)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@26c34e80, amount: 0
...
all are "amout : 0" here
...
230606 15:38:31.446(T168770)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7cc0aa5, amount: 0
230606 15:38:31.446(T168770)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3690868a, amount: 284068
230606 15:38:38.052(T175376)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:38:52.646(T189970)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 2019186
230606 15:38:52.646(T189970)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:38:57.647(T194971)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:38:57.647(T194971)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1584594
230606 15:38:57.647(T194971)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:39:02.647(T199971)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:39:02.648(T199972)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:39:16.624(T213948)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1987774
230606 15:39:16.624(T213948)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:39:21.624(T218948)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:39:21.625(T218949)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@3690868a, amount: 284068
230606 15:39:27.609(T224933)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:39:41.703(T239027)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 3084146
230606 15:39:41.703(T239027)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:39:46.703(T244027)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:39:46.704(T244028)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 2707545
230606 15:39:46.704(T244028)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:39:51.704(T249028)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:39:51.705(T249029)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2821d066, amount: 670158
230606 15:40:05.814(T263138)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 3041039
230606 15:40:05.814(T263138)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230606 15:40:10.815(T268139)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230606 15:40:10.815(T268139)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Time for complete write cycle.
230606 15:40:10.815(T268139)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@1dd46656, amount: 0
230606 15:40:10.815(T268139)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6f1e4ccd, amount: 0
...
all are "amout : 0" here
...
230606 15:40:10.816(T268140)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7bcb52f9, amount: 0
230606 15:40:10.816(T268140)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6feba602, amount: 0
230606 15:40:10.816(T268140)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6ece4c0, amount: 1064960
230606 15:40:33.942(T291266)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@60b07181, amount: 0
...
all are "amout : 0" here
...
230606 15:40:33.944(T291268)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7ab4d9c4, amount: 0
230606 15:40:33.944(T291268)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@61387304, amount: 1064960

The DownloadDataWriter-Threads are triggered even there is no data to write, why?
There is even disc activtiy I dont know what is written here all the time, empty buffers?

Using iotop:
shows always around 100-200kb writing IO. The threads appear like in the log additionaly in the same period they appear in the log.

If I shutdown phex it takes forever since every thread writes its big but empty buffer for each file (800 files in download list), most of the them are 0% level because they are orphaned in the gnutella network but they are activated for downloading, not stopped.

GregorK · #5 (**permalink**) June 6th, 2023

I'm pretty sure 0 bytes are not written to disk. I would rather call this a flaw in the logging.
But of course it could be very likely that things are not optimal. There are multiple causes that trigger a write. Also it could be a programming problem or a race condition that is causing excessive write. So its not easy to say why it happens.

If you want to dig into this I would suggest you attempt to also log out the variable values you find in the if conditions in DownloadDataWriter.writeDownloadData().
Line 137/138, Line 158/159 and Line 181.

You might also like to multiple in Line 138 the DateUtils.MILLIS_PER_MINUTE with maybe 5 and see if it makes a difference.

kermithermos · #6 (**permalink**) June 7th, 2023

Thank you for your helpful answer:

Maybe I am wrong here and overlooked something:

When I looked at the logs, every 5 sec a write is going on. most of them are 0 bytes written messages. So I searched for 5000 (ms) in the code (DownloadDataWriter) and there you go:
Line 111:

Code:

wait( 5000 );

This should be at least a random value in a range, to spread the time when the threads are served again. They are all set to 5000 and are notified the same time again and most of them wait again 5000ms,...

Every thread waits the same time, that means they wake up at the same time, and later additional comes on top the forced write in Line 137/138. That means: A much higher buffersize with this 5000ms is totally ignored if you have not much downloadtraffic thats why it is never filled to an expected level, its flushed far too soon.
You can use a random value here to "spread" the threads more, set up the forced write time but the inefficient buffer usesage still exists, bec. wait time and downloads speed depend on each other to effeciencely use the buffer. You can use different values for different speeds for improved effiencency but this is still a even more bad hack.
Thats why this time check based implementation IMO is not a good solution.

My idea:
The buffer itself should write data when it reaches the 90% level independent from a time. If buffer reaches 90% enter a data writing queue and pause downloading for this file until buffer is flushed. This is easy to implement and dont have to struggle with different thread situations.

GregorK · #7 (**permalink**) June 8th, 2023

Hmm.. So there is a single DownloadDataWriter thread that should wake every 5 seconds to check if any buffer is full. Its a single thread, so I don't see why a random value should change anything.

This check should not cause writing if buffers are not full (L158/L181). So something else must be going wrong there too.

Additional at least every minute a write is forced (L137/138), maybe earlier if buffers run full (L120).

I did some changes to DownloadDataWriter to have more correct logging. Hope this might help:
https://sourceforge.net/p/phex/code/4572/
The line number above are before my changes.

GregorK · #8 (**permalink**) June 8th, 2023

This is how it looks for me now

Code:

230608 10:31:35.824(T60119)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:31:35.824(T60119)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Time for complete write cycle.
230608 10:31:35.824(T60119)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:31:35.824(T60119)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@2c4947fa, amount: 225280 bytes.
230608 10:31:35.837(T60132)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@16e84b3f, amount: 16384 bytes.
230608 10:31:35.840(T60135)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@5294c4, amount: 16384 bytes.
230608 10:31:35.843(T60138)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7007e514, amount: 893365 bytes.
230608 10:31:35.881(T60176)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@384c68bd, amount: 632250 bytes.
230608 10:31:35.900(T60195)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@21fede92, amount: 331776 bytes.
230608 10:31:35.910(T60205)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@79af60e, amount: 613260 bytes.
230608 10:31:35.927(T60222)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6233ef0d, amount: 540672 bytes.
230608 10:31:35.940(T60235)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 3269371 bytes.
230608 10:31:35.940(T60235)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total data written was: 3269371 bytes.
230608 10:31:35.941(T60236)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:31:40.946(T65241)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:31:40.946(T65241)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:31:40.946(T65241)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 327158 bytes.
230608 10:31:40.946(T65241)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:31:40.946(T65241)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:31:45.958(T70253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:31:45.958(T70253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:31:45.958(T70253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 641733 bytes.
230608 10:31:45.958(T70253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:31:45.958(T70253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:31:50.959(T75254)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:31:50.959(T75254)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:31:50.959(T75254)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 943725 bytes.
230608 10:31:50.959(T75254)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:31:50.959(T75254)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:31:55.965(T80260)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:31:55.965(T80260)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:31:55.965(T80260)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1258300 bytes.
230608 10:31:55.965(T80260)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:31:55.965(T80260)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:00.970(T85265)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:00.970(T85265)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:00.970(T85265)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1396661 bytes.
230608 10:32:00.970(T85265)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:00.970(T85265)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:05.984(T90279)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:05.984(T90279)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:05.985(T90280)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1472691 bytes.
230608 10:32:05.985(T90280)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:05.985(T90280)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:10.997(T95292)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:10.997(T95292)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:10.997(T95292)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1548721 bytes.
230608 10:32:10.997(T95292)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:10.997(T95292)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:16.002(T100297)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:16.002(T100297)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:16.002(T100297)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1568316 bytes.
230608 10:32:16.002(T100297)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:16.002(T100297)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:21.010(T105305)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:21.010(T105305)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:21.010(T105305)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1644092 bytes.
230608 10:32:21.010(T105305)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:21.010(T105305)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:26.024(T110319)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:26.024(T110319)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:26.024(T110319)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1715772 bytes.
230608 10:32:26.024(T110319)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:26.024(T110319)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:31.029(T115324)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:31.029(T115324)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:31.029(T115324)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1818172 bytes.
230608 10:32:31.029(T115324)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:31.029(T115324)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:36.037(T120332)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:36.037(T120332)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Time for complete write cycle.
230608 10:32:36.037(T120332)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:36.037(T120332)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@1134a9e2, amount: 147456 bytes.
230608 10:32:36.041(T120336)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@7007e514, amount: 171595 bytes.
230608 10:32:36.046(T120341)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@384c68bd, amount: 653894 bytes.
230608 10:32:36.076(T120371)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@79af60e, amount: 844916 bytes.
230608 10:32:36.095(T120390)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@6233ef0d, amount: 311 bytes.
230608 10:32:36.096(T120391)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 1818172 bytes.
230608 10:32:36.096(T120391)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total data written was: 1818172 bytes.
230608 10:32:36.096(T120391)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:41.106(T125401)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:41.106(T125401)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:41.106(T125401)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 0 bytes.
230608 10:32:41.106(T125401)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:41.106(T125401)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 10:32:46.111(T130406)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 10:32:46.111(T130406)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 9437184 - MaxTotalDownloadWriteBuffer 37748736
230608 10:32:46.111(T130406)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 299801 bytes.
230608 10:32:46.111(T130406)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 10:32:46.111(T130406)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...

kermithermos · #9 (**permalink**) June 8th, 2023

Yes you are right its only one tread, I thought there were several for each file.

I interpreted these kind of lines wrong ...

Code:

...
230608 15:13:09.432(T684351)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.432(T684351)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.432(T684351)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.443(T684362)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.443(T684362)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.443(T684362)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.455(T684374)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.455(T684374)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.455(T684374)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.466(T684385)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.466(T684385)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.466(T684385)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.477(T684396)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.477(T684396)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
230608 15:13:09.477(T684396)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.
...

... as different threads but the thread number 15 is always the same.

I tested your new version.
Now my settings for buffer size are correctly used and/or the logger handles displays it right now. Buffers are flushed about 90% and it is more or less identical with the output from iotop. Great!

Code:

230608 15:15:22.334(T817253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 5242880 bytes.
230608 15:15:22.334(T817253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total data written was: 5242880 bytes.
230608 15:15:22.334(T817253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Time for complete write cycle.
230608 15:15:22.334(T817253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 4718592 - MaxTotalDownloadWriteBuffer 37748736
230608 15:15:22.334(T817253)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Trigger buffer write for phex.download.swarming.SWDownloadFile@585a9eb3, amount: 3895740 bytes.
230608 15:15:28.572(T823491)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 3895740 bytes.
230608 15:15:28.572(T823491)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total data written was: 3895740 bytes.
230608 15:15:28.572(T823491)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 15:15:41.018(T835937)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 15:15:41.018(T835937)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 4718592 - MaxTotalDownloadWriteBuffer 37748736
230608 15:15:41.018(T835937)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 3263005 bytes.
230608 15:15:41.018(T835937)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 15:15:41.018(T835937)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 15:15:51.284(T846203)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 15:15:51.285(T846204)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 4718592 - MaxTotalDownloadWriteBuffer 37748736
230608 15:15:51.285(T846204)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 3263005 bytes.
230608 15:15:51.285(T846204)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 15:15:51.285(T846204)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...
230608 15:16:15.839(T870758)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Woke...
230608 15:16:15.839(T870758)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: MaxWriteBufferPerDownload 4718592 - MaxTotalDownloadWriteBuffer 37748736
230608 15:16:15.839(T870758)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Total buffered data was: 4344349 bytes.
230608 15:16:15.839(T870758)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: No data was written
230608 15:16:15.839(T870758)(156) DEBUG/phex.download.DownloadDataWriter [DownloadDataWriter]:: Waiting...

GregorK · #10 (**permalink**) June 8th, 2023

This log line

Code:

230608 15:13:09.477(T684396)(156) DEBUG/phex.download.DownloadDataWriter [SWDownloadWorker-55a0eb24-PhexPool-thread-15]:: Triggering write cycle.

indicates that thread-15 is telling the DownloadDataWriter thread that his buffer is full. You could see multiple threads calling this or the same thread calling this very often. Its only a wake up call to the DownloadDataWriter thread to start flushing the buffers.