View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0001837 | CCdciel | General | public | 17-11-08 13:02 | 17-11-11 12:06 |
| Reporter | tango13 | Assigned To | Patrick Chevalley | ||
| Priority | normal | Severity | minor | Reproducibility | always |
| Status | resolved | Resolution | no change required | ||
| Platform | Odroid XU4 | OS | Raspbian | OS Version | stretch |
| Product Version | 0.9 | ||||
| Target Version | 1.0 | ||||
| Summary | 0001837: 10 seconds minimum for download | ||||
| Description | Hi Patrick, trying rev625 I noticed that the download of the image doesn't start before 10 seconds. If the exposure is longer than 10 s then nothing different happens, apart from the fact that the exposure countdown appears after 10 sec. If the exposure is shorter that 10 s then CCDciel starts downloading the image only after 10s, even if the exposure time is already terminated. For example, for a 2-second exposure the download starts after 8 seconds after the exposure time is over. Thank you. | ||||
| Tags | No tags attached. | ||||
|
|
I add some timing information for the camera frame processing in revision 629: https://sourceforge.net/p/ccdciel/code/629/ To activate this additional messages you have to uncomment (remove //) for the line {$define camera_debug} at the top of cu_camera.pas and cu_indicamera.pas before to compile the program. Copy here the messages from a capture. For me using a 2 second exposure with a 6 megapixel ccd simulator it give the following: 15:04:20:Start single preview 15:04:21:CCD Simulator: progress: 2.0 15:04:21:CCD Simulator: progress: 1.3 15:04:22:CCD Simulator: progress: 0.3 15:04:22:CCD Simulator: progress: 0.0 15:04:23:CCD Simulator: progress: 0.0 15:04:23:CCD Simulator: receive blob 15:04:23:CCD Simulator: this is a fits file 15:04:23:CCD Simulator: copy stream 15:04:23:CCD Simulator: NewImage 15:04:23:CCD Simulator: load stream 15:04:24:CCD Simulator: write headers 15:04:24:CCD Simulator: display image 15:04:24:End preview The "downloading" status display it triggered by the first "progress: 0.0". The time it take between the first "progress: 0.0" and "receive blob" include a lot of processing that cannot be traced here, this comprise the following: - indi driver actually read the image from the camera - indi server encode the data in base64 and send the xml message - indi client receive the xml message and decode the data |
|
|
Hi Patrick, this is what shows up on my Odroid XU4, armbian stretch/sid ccdciel rev 630, indi commit 36a4539b5e10d0afce3b1f3a39fb989b32db56e3 Wed Nov 8 09:06:03 2017 +0300 17:49:08:Start single preview 17:49:09:CCD Simulator: [INFO] Upload settings set to local only. 17:49:19:CCD Simulator: progress: 2.0 17:49:19:CCD Simulator: progress: 0.0 17:49:19:CCD Simulator: load stream 17:49:21:CCD Simulator: write headers 17:49:21:CCD Simulator: display image 17:49:21:CCD Simulator: progress: 0.0 17:49:24:End preview This is what instead shows on my RasPi3, raspbian 9.1 ccdciel rev 630, indi commit 6dfa98091bce1919f751207683228859ce5b8c27 Sun Nov 5 10:01:05 2017 +0300 12:04:35:Start single preview 12:04:43:CCD Simulator: progress: 2.0 12:04:43:CCD Simulator: progress: 0.0 12:04:54:CCD Simulator: progress: 0.0 12:04:54:CCD Simulator: receive blob 12:04:54:CCD Simulator: this is a fits file 12:04:54:CCD Simulator: copy stream 12:04:54:CCD Simulator: NewImage 12:04:54:CCD Simulator: load stream 12:04:58:CCD Simulator: write headers 12:04:58:CCD Simulator: display image 12:05:06:End preview Could it be something related to INDI too? Thank you. |
|
|
Some of the difference in the messages is because you use network transfer with the RPi but ram disk transfer with the Odroid. There is two long delay. 10 seconds before to receive the first progress indicator and in the network case 10 seconds between "progress:0.0" and "receive blob" It can be interesting to activate INDI debug log for the camera, including "Driver debug". For me with the ccd simulator this give: DEBUG 54.157212 sec : pprx: 96153.8 pixels per radian ppry: 96153.8 pixels per radian ScaleX: 2.14552 arcsecs/pixel ScaleY: 2.14552 arcsecs/pixel DEBUG 54.157257 sec : Lookup radius 29.31 DEBUG 54.157276 sec : gsc -c 224.792045 +15.070428 -r 29.3 -m 0 17.00 -n 3000 DEBUG 56.165961 sec : Uploading file. Ext: fits, Size: 2626560, sendImage? Yes, saveImage? No DEBUG 56.175243 sec : Upload complete Unfortunately the time is in second since the driver is started. You can tail -f the log file to check if the first 3 messages are given immediately after you click the Preview button in CCDciel. The 2 seconds wait before " Uploading file..." is the exposure time. The last 2 messages indicate the network upload time. |
|
|
Also, please upgrade to revision 633 where I add a log with the full INDI protocol received by the indi client. https://sourceforge.net/p/ccdciel/code/633/ Be sure {$define camera_debug} is not commented before to compile. Do only connection and take one preview before to close the program because the log file can be very big. This can also slow down all the operations. Zip and upload here the file /tmp/ccdciel_indicamera.log |
|
|
Please find attached the log files, I'll try also to enable INDI debug and let you know. Thank you. |
|
|
This is the INDI debug output: INFO 1866.990401 sec : Debug is enabled. INFO 1887.266024 sec : Upload settings set to local only. DEBUG 1887.295234 sec : pprx: 110526 pixels per radian ppry: 110526 pixels per radian ScaleX: 1.86652 arcsecs/pixel ScaleY: 1.86652 arcsecs/pixel DEBUG 1887.295801 sec : Lookup radius 79.16 DEBUG 1887.296126 sec : gsc -c 224.788760 +15.070436 -r 79.2 -m 0 11.00 -n 3000 DEBUG 1897.588429 sec : Uploading file. Ext: fits, Size: 24744960, sendImage? No, saveImage? Yes INFO 1897.643145 sec : Image saved to /tmp/ccdciel_tmp.fits DEBUG 1897.643958 sec : Upload complete And this is the output (and timing) of gsc: piero@xu4:~$ time gsc -c 224.788760 +15.070436 -r 79.2 -m 0 11.00 -n 3000 0092401344 224.56737 +14.03758 0.0 6.78 0.00 4 0 +056 F; 63.29 192 0092400438 224.01663 +14.16709 0.3 10.92 0.40 1 0 00J0 F; 70.34 220 0092400462 224.11926 +14.23620 0.3 9.34 0.40 1 0 00J0 F; 63.37 218 0092400292 224.59661 +14.32961 0.3 10.84 0.40 1 0 00J0 T; 45.83 194 0092400292 224.59669 +14.32970 0.3 10.25 0.40 1 0 00G1 T; 45.82 194 0092400210 223.79769 +14.38974 0.2 10.46 0.40 1 0 00G1 T; 70.54 235 0092400210 223.79754 +14.38980 0.3 10.96 0.40 1 0 00J0 T; 70.54 235 0092400187 224.61562 +14.39852 0.3 10.21 0.40 1 0 00J0 T; 41.55 194 0092400187 224.61569 +14.39856 0.2 9.80 0.40 1 0 00G1 T; 41.54 194 0092400184 224.05526 +14.44590 0.3 5.57 0.40 1 3 00G1 T; 56.70 229 0092400184 224.05512 +14.44625 0.0 5.78 0.00 4 0 +056 T; 56.70 229 0092400017 223.71852 +14.45452 0.2 10.52 0.40 1 0 00G1 T; 72.26 239 0092400017 223.71843 +14.45462 0.3 10.92 0.40 1 0 00J0 T; 72.26 239 0092400281 224.56731 +14.48075 0.2 9.27 0.40 1 0 00G1 T; 37.64 200 0092400281 224.56724 +14.48081 0.3 9.76 0.40 1 0 00J0 T; 37.64 200 0092400126 224.03622 +14.51660 0.2 9.01 0.40 1 0 00G1 F; 54.86 233 0092400204 224.34383 +14.56162 0.2 10.56 0.40 1 0 00G1 F; 39.98 220 0092400182 223.91318 +14.60238 0.2 10.56 0.40 1 0 00G1 F; 58.03 241 0092400114 224.67877 +14.84619 0.2 10.31 0.40 1 0 00G1 F; 14.89 205 0092400120 223.79179 +14.87517 0.1 10.80 0.40 1 0 00G1 F; 58.96 259 0092400063 223.78489 +14.91398 0.1 10.59 0.40 1 0 00G1 F; 58.93 261 0092400062 223.47876 +14.97109 0.1 10.30 0.40 1 0 00G1 F; 76.15 266 0092400077 223.75431 +14.97919 0.3 6.86 0.40 1 0 00G1 T; 60.19 265 0092400077 223.75450 +14.97944 0.1 6.88 0.00 4 0 +056 T; 60.18 265 0092500865 225.08984 +13.92244 0.2 10.92 0.40 1 0 00J0 F; 71.07 166 0092501397 225.51301 +14.03399 0.3 9.34 0.40 1 0 00J0 F; 75.07 146 0092501109 225.59248 +14.07795 0.3 10.30 0.40 1 0 00J0 F; 75.66 142 0092500212 225.71368 +14.26770 0.3 9.34 0.40 1 3 00J0 T; 72.12 132 0092500212 225.71373 +14.26809 0.3 8.34 0.40 1 3 00G1 T; 72.11 132 0092500017 225.00331 +14.35066 0.3 10.09 0.40 1 0 00J0 T; 44.95 164 0092500017 225.00338 +14.35079 0.3 9.55 0.40 1 0 00G1 T; 44.94 164 0092500021 225.01167 +14.37063 0.3 10.51 0.40 1 0 00G1 T; 43.94 163 0092500071 225.06199 +14.42379 0.3 9.92 0.40 1 0 00J0 T; 41.91 158 0092500071 225.06200 +14.42389 0.3 9.55 0.40 1 0 00G1 T; 41.91 158 0092500213 224.73629 +14.44473 0.3 10.84 0.40 1 0 00J0 T; 37.67 185 0092500213 224.73648 +14.44474 0.2 10.46 0.40 1 0 00G1 T; 37.66 185 0092500036 225.61348 +14.58985 0.3 9.80 0.40 1 0 00G1 F; 55.85 121 0092500057 225.83514 +14.71570 0.2 10.21 0.40 1 0 00G1 F; 64.30 109 0092500264 225.22151 +14.75680 0.2 10.21 0.40 1 0 00G1 F; 31.36 127 0092500144 226.04496 +14.75817 0.3 8.42 0.40 1 0 00G1 F; 75.20 104 0092500174 224.99029 +14.83311 0.2 6.87 0.40 1 0 00G1 T; 18.42 141 0092500174 224.99017 +14.83325 0.1 7.19 0.00 4 0 +056 T; 18.41 141 0092500194 224.99778 +14.85726 0.2 10.21 0.40 1 0 00G1 F; 17.62 137 0148500341 225.57302 +14.99996 0.2 10.88 0.40 1 0 00G1 F; 45.64 95 0148500175 225.70704 +15.04052 0.2 8.80 0.40 1 0 00G1 F; 53.24 92 0148500593 224.58447 +15.04144 0.1 10.14 0.40 1 0 00G1 F; 11.96 262 0148500294 224.44800 +15.05875 0.1 7.50 0.10 4 0 +056 T; 19.76 268 0148500294 224.44792 +15.05883 0.2 6.83 0.40 1 0 00G1 T; 19.76 268 0148500466 224.76161 +15.07905 0.2 7.79 0.40 1 0 00G1 F; 1.66 288 0148500478 225.56287 +15.08484 0.2 7.96 0.40 1 0 00G1 F; 44.86 89 0148500154 225.46432 +15.10605 0.2 8.97 0.40 1 0 00G1 F; 39.19 87 0148500407 224.62572 +15.13204 0.1 9.75 0.40 1 0 00G1 F; 10.14 291 0148500631 224.46513 +15.15215 0.1 10.88 0.40 1 0 00G1 F; 19.38 285 0148500199 225.37471 +15.17198 0.2 10.26 0.40 1 0 00G1 F; 34.48 80 0148500558 224.21068 +15.23604 0.2 10.84 0.40 1 3 00G1 F; 34.92 287 0148500829 224.48970 +15.24915 0.1 10.89 0.40 1 0 00G1 F; 20.37 302 0148500218 225.94004 +15.26148 0.2 9.71 0.40 1 0 00G1 F; 67.65 80 0148500244 225.81451 +15.26810 0.2 9.22 0.40 1 0 00G1 F; 60.57 79 0148500599 225.54099 +15.28816 0.2 8.67 0.40 1 0 00G1 F; 45.48 73 0148500188 226.00729 +15.33612 0.2 9.96 0.40 1 0 00G1 F; 72.33 77 0148500815 225.89564 +15.42151 0.2 7.91 0.40 1 0 00G1 F; 67.45 72 0148500838 225.69135 +15.45831 0.2 10.51 0.40 1 0 00G1 F; 57.19 66 0148500190 224.32138 +15.47687 0.1 9.14 0.40 1 0 00G1 F; 36.42 312 0148500522 226.00832 +15.48426 0.2 10.88 0.40 1 0 00G1 F; 74.83 70 0148500486 224.76137 +15.61378 0.1 10.14 0.40 1 0 00G1 F; 32.64 357 0148500331 225.66262 +15.77472 0.1 9.71 0.40 1 0 00G1 F; 65.88 50 0148500347 225.46642 +15.78140 0.1 8.38 0.40 1 0 00G1 F; 57.93 42 0148500383 225.46774 +15.78850 0.1 8.17 0.40 1 0 00G1 F; 58.30 42 0148500643 225.37434 +15.87001 0.2 8.80 0.40 1 0 00G1 F; 58.72 35 0148500644 224.57183 +15.87206 0.1 10.67 0.37 1 0 00G1 F; 49.71 345 0148500726 225.45538 +15.92581 0.1 10.21 0.40 1 0 00G1 F; 64.18 37 0148500887 224.36356 +15.99332 0.1 10.85 0.34 1 0 00G1 F; 60.58 336 0148500857 224.82241 +16.00481 0.1 10.92 0.37 1 0 00G1 F; 56.10 2 0148500728 225.63882 +16.05447 0.2 6.98 0.40 1 0 00G1 T; 76.81 40 0148500728 225.63775 +16.05495 0.1 7.00 0.00 4 0 +056 T; 76.79 40 0148500678 225.15212 +16.10635 0.1 9.42 0.37 1 0 00G1 F; 65.61 19 0148500636 225.15229 +16.12220 0.1 10.30 0.37 1 0 00G1 F; 66.51 18 0148500489 225.25880 +16.15911 0.2 8.09 0.37 1 0 00G1 F; 70.74 23 0148500250 225.25764 +16.25093 0.1 8.42 0.37 1 0 00G1 F; 75.83 21 0148500120 225.08999 +16.28375 0.1 10.96 0.37 1 0 00G1 F; 74.85 13 0147800468 223.48933 +15.05570 0.1 10.14 0.40 1 0 00G1 F; 75.29 269 0147800596 223.79110 +15.31679 0.1 9.44 0.40 1 0 00G1 F; 59.63 284 0147800819 223.70827 +15.32526 0.1 6.32 0.40 1 0 00G1 T; 64.40 284 0147800819 223.70821 +15.32533 0.1 7.19 0.00 4 0 +056 T; 64.41 284 0147800738 223.98002 +15.33626 0.1 10.30 0.40 1 0 00G1 F; 49.47 289 0147800362 223.79206 +15.46655 0.1 10.80 0.38 1 0 00G1 F; 62.39 293 0147800425 223.57528 +15.53006 0.2 8.30 0.38 1 0 00G1 F; 75.45 292 0147800521 223.69530 +15.58689 0.1 10.86 0.37 1 0 00G1 F; 70.45 296 0147800748 223.86586 +15.64369 0.1 10.77 0.37 1 0 00G1 F; 63.52 303 0147800815 223.68667 +15.71141 0.1 10.81 0.37 1 0 00G1 F; 74.46 301 0147800780 223.70017 +15.75014 0.1 10.67 0.35 1 0 00G1 F; 75.02 303 0147800635 223.93094 +15.84011 0.1 10.84 0.34 1 0 00G1 F; 67.78 313 real 0m0.061s user 0m0.045s sys 0m0.015s |
|
|
From the ccdciel_indicamera log: - 10:17:35.726 ccdciel send the exposure parameters for a 2 second exposure and saving the result file to /tmp - 10:17:35.841 we receive confirmation from indi with the new parameters. then nothing for 10 seconds until - 10:17:46.342 we receive at the same time the 2 and 0 sec. progress indicator, both with a UT timestamp 2017-11-10T09:17:46 - 10:17:46.527 we receive the information the file is saved also with the same timestamp 2017-11-10T09:17:46 The timestamp written by the indi server when it send the message confirm the problem is not a delay in the message transmission. But indi is really waiting 10 seconds after it receive the exposure parameters and send the confirmation. |
|
|
The Indi debug log confirm this 10 second wait. As you tested the problem is not the gsc command. But after it get the star list, the camera simulator need to plot them on the bitmap. Maybe this is this plot function that require a lot of time with the arm processor? Can you do the same operation but using a simple Indi client, from indistarter or other, with ccdciel not running . - set the same image size - set Upload to local - set Expose duration to 2 and click Set. Do it also take 10 seconds before you see the message "[INFO] Image saved to..." ? |
|
|
Also, can you produce the same log with a real camera ? |
|
|
Also with indistarter Indi client the behaviour is the same and the 10 second wait shows up. I will also try with a real camera but at this point I strongly suspect this wait is related to the image setup time of the ccd simulator. That's because if I reduce the size of the simulated image, the wait reduces accordingly. With an image of, say, 1024x768 px then there's no wait at all and the timing of the whole process is back to normal. I think with a real camera, since I guess there's no image setup time at all, things will work with no problems. What do you think? |
|
|
This is for a 4096x3520 simulated image, 2s exposure: DEBUG 1091.798861 sec : pprx: 110526 pixels per radian ppry: 110526 pixels per radian ScaleX: 1.86652 arcsecs/pixel ScaleY: 1.86652 arcsecs/pixel DEBUG 1091.799314 sec : Lookup radius 79.16 DEBUG 1091.799547 sec : gsc -c 224.793052 +15.070437 -r 79.2 -m 0 11.00 -n 3000 DEBUG 1102.018909 sec : Uploading file. Ext: fits, Size: 24744960, sendImage? No, saveImage? Yes INFO 1102.117157 sec : Image saved to /home/piero/IMAGE_002.fits DEBUG 1102.117348 sec : Upload complete This is for a 1024x768 simulated image, 2s exposure: DEBUG 1183.218107 sec : pprx: 110526 pixels per radian ppry: 110526 pixels per radian ScaleX: 1.86652 arcsecs/pixel ScaleY: 1.86652 arcsecs/pixel DEBUG 1183.218883 sec : Lookup radius 19.91 DEBUG 1183.219257 sec : gsc -c 224.790708 +15.070437 -r 19.9 -m 0 17.00 -n 3000 DEBUG 1185.268896 sec : Uploading file. Ext: fits, Size: 1578240, sendImage? No, saveImage? Yes INFO 1185.312360 sec : Image saved to /home/piero/IMAGE_003.fits DEBUG 1185.312933 sec : Upload complete |
|
|
Yes, the big simulation image is probably the cause of the problem. With a real camera I expect this problem is not present. But it is possible that another problem slow down the capture. This can be the image transfer on the USB, then to the disk or the network, and finally the processing and display in ccdciel. I suggest we keep this issue open until you can try with a real camera. In case of performance problem you can try to produce this same logs to help to identify the cause. |
|
|
Hi Patrick, with my real camera, which produces big files so we're in the worst case, no problems at all: 18:51:22:Start single preview 18:51:23:ZWO CCD ASI1600MM-Cool: progress: 2.0 18:51:23:ZWO CCD ASI1600MM-Cool: [DEBUG] StartExposure->setexp : 2.000s 18:51:23:ZWO CCD ASI1600MM-Cool: progress: 1.9 18:51:23:ZWO CCD ASI1600MM-Cool: progress: 1.6 18:51:23:ZWO CCD ASI1600MM-Cool: progress: 1.4 18:51:23:ZWO CCD ASI1600MM-Cool: progress: 1.1 18:51:24:ZWO CCD ASI1600MM-Cool: progress: 0.9 18:51:24:ZWO CCD ASI1600MM-Cool: progress: 0.6 18:51:24:ZWO CCD ASI1600MM-Cool: progress: 0.4 18:51:24:ZWO CCD ASI1600MM-Cool: progress: 0.1 18:51:25:ZWO CCD ASI1600MM-Cool: progress: 0.0 18:51:26:ZWO CCD ASI1600MM-Cool: [DEBUG] Uploading file. Ext: fits, Size: 32783040, sendImage? No, saveImage? Yes 18:51:26:ZWO CCD ASI1600MM-Cool: load stream 18:51:29:ZWO CCD ASI1600MM-Cool: write headers 18:51:29:ZWO CCD ASI1600MM-Cool: display image 18:51:29:ZWO CCD ASI1600MM-Cool: progress: 0.0 18:51:30:End preview DEBUG 871.163447 sec : StartExposure->setexp : 2.000s DEBUG 874.253115 sec : Uploading file. Ext: fits, Size: 32783040, sendImage? No, saveImage? Yes INFO 874.358028 sec : Image saved to /tmp/ccdciel_tmp.fits DEBUG 874.358361 sec : Upload complete I've noticed that if I use the "zoom to adjust in window" feature the total preview process takes around 3 seconds more than if I use the 1:1 zoom, but that I guess is due to the extra image processing needed to resample the image, right? Anyway, it looks like CCDciel is working fine, and the more I know it, the more I like it :) Thank you very much! P.S. I didn't have the chance to thank you also for the highlight and shadow clipping feature, it is extremely useful for CMOS cameras! |
|
|
Thank you for the testing, this is an interesting case where the simulator is slower than the real camera. This is not bad for a 16 megapixel image and an ARM processor. Yes, resizing the image is more costly than cropping a 1:1 part. You can speedup the initial setup of the target by using 4x4 binning for the preview and plate solved slewing, then use binning 1x1 in capture. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 17-11-08 13:02 | tango13 | New Issue | |
| 17-11-09 15:28 | Patrick Chevalley | Assigned To | => Patrick Chevalley |
| 17-11-09 15:28 | Patrick Chevalley | Status | new => feedback |
| 17-11-09 15:28 | Patrick Chevalley | Target Version | => 1.0 |
| 17-11-09 15:28 | Patrick Chevalley | Note Added: 0004245 | |
| 17-11-09 18:10 | tango13 | Note Added: 0004247 | |
| 17-11-09 18:10 | tango13 | Status | feedback => assigned |
| 17-11-09 18:39 | Patrick Chevalley | Note Added: 0004248 | |
| 17-11-09 19:08 | Patrick Chevalley | Note Added: 0004249 | |
| 17-11-09 19:08 | Patrick Chevalley | Status | assigned => feedback |
| 17-11-10 10:27 | tango13 | File Added: indicameralog.tar.gz | |
| 17-11-10 10:27 | tango13 | Note Added: 0004251 | |
| 17-11-10 10:27 | tango13 | Status | feedback => assigned |
| 17-11-10 10:37 | tango13 | Note Added: 0004252 | |
| 17-11-10 12:57 | Patrick Chevalley | Note Added: 0004254 | |
| 17-11-10 13:09 | Patrick Chevalley | Status | assigned => feedback |
| 17-11-10 13:09 | Patrick Chevalley | Note Added: 0004255 | |
| 17-11-10 13:15 | Patrick Chevalley | Note Added: 0004256 | |
| 17-11-10 14:27 | tango13 | Note Added: 0004257 | |
| 17-11-10 14:27 | tango13 | Status | feedback => assigned |
| 17-11-10 14:38 | tango13 | Note Added: 0004258 | |
| 17-11-10 18:15 | Patrick Chevalley | Note Added: 0004259 | |
| 17-11-10 19:11 | tango13 | Note Added: 0004260 | |
| 17-11-11 12:06 | Patrick Chevalley | Status | assigned => resolved |
| 17-11-11 12:06 | Patrick Chevalley | Resolution | open => no change required |
| 17-11-11 12:06 | Patrick Chevalley | Note Added: 0004261 |
