<html><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; ">Hi Lennart,<div> <div><div>On Jun 21, 2008, at 4:15 PM, Lennart Poettering wrote:</div><blockquote type="cite"><div> Is I tried to point out to you your code was heavily racy. I would assume that the weirdness you are experiencing with the put hook is mostly caused by this.</div></blockquote><div> </div>You are right that the code you offered to look at last week incorrectly used pa_thread in an inappropriate way.  </div><div> </div><div>However that was not the code attached to the end of the email.  It has no threads, no ipc.</div><div> </div><div>The code attached to the email, was a stripped module that attaches hooks to all of the hooks available to a sink input, and in addition installs a subscription event handler.</div><div> </div><div>The subscription function is called before a file streams, the _put hook, after the file streams.  </div><div><blockquote type="cite"><div><blockquote type="cite"></blockquote></div></blockquote> <div><blockquote type="cite">The subscription event is triggered at exactly the same place as the</blockquote></div><blockquote type="cite"><div>_PUT hook: <a href="http://git.0pointer.de/?p=pulseaudio.git;a=blob;f=src/pulsecore/sink-input.c;h=07ddb83af48b3b1ea8e6e90ca339a2cb1b031725;hb=refs/heads/tags/release-0.9.10#l390">http://git.0pointer.de/?p=pulseaudio.git;a=blob;f=src/pulsecore/sink-input.c;h=07ddb83af48b3b1ea8e6e90ca339a2cb1b031725;hb=refs/heads/tags/release-0.9.10#l390</a> </div></blockquote><div> </div><div>Agreed.  </div><div> </div><div>The callbacks are marked for calling next to each other in sink-input.c.  </div><div> </div><div>There is a big delay between the two registered routines are called back.  </div><div> </div><div>The delay seems equivalent to the length of a file being streamed.</div><div> </div><div><blockquote type="cite" class=""> E: > pa__init E: this version compiled - Jun 23 2008 14:25:37 E: < pa__init E: called at 1214256366.393001 E:    delta between last time called is 20237606(m) 04(s) 393001 (usec) I: module.c: Loaded "module-test-sink-input" (index: #9; argument: ""). I: client.c: Created 1 "Native client (UNIX socket client)" I: protocol-native.c: Got credentials: uid=1000 gid=1000 success=1 I: protocol-native.c: Enabled SHM for new connection I: client.c: Client 1 changed name from "Native client (UNIX socket client)" to "paplay" E: <  sink_input_new_hook E: called at 1214256407.739320 E:    delta between last time called is 00(m) 40(s) 346319 (usec) E: called at 1214256407.739335 E:    delta between last time called is 000015 (usecs) E: last message indicates approx overhead for log_time E: < sink_input_fixate_hook E: called at 1214256407.739359 E:    delta between last time called is 000024 (usecs) I: sink-input.c: Created input 0 "/home/nick/Sony CD-ROM Test Disk Type <a href="mailto:3.0/1-KHz-0030_-@0dB.wav">3.0/1-KHz-0030_-@0dB.wav</a>" on usbAudio with sample spec s16le 2ch 44100Hz and channel map front-left,front-right E: > subscribe_callback E: subscribe_callback - new event received on sink-input with index 0 E: < subscribe_callback: E: called at 1214256407.739466 E:    delta between last time called is 000107 (usecs) E: < sink_input_put_hook E: called at 1214256439.738896 E:    delta between last time called is 00(m) 23(s) 000570 (usec) E: < sink_input_unlink_hook E: called at 1214256439.738964 E:    delta between last time called is 000068 (usecs) I: sink-input.c: Freeing output 0 "/home/nick/Sony CD-ROM Test Disk Type <a href="mailto:3.0/1-KHz-0030_-@0dB.wav">3.0/1-KHz-0030_-@0dB.wav</a>" E: > subscribe_callback E: < subscribe_callback - not a new sink input I: client.c: Freed 1 "paplay" I: protocol-native.c: connection died.  </blockquote> </div><div>From the instrumented run above the subscription callback is called at 1214256407.739466, about 107 microseconds after the fixate hook is called.  The put hook is called at 1214256407.739466, 23 or so seconds later.  The file being played is marked on the test CD as being thirty seconds, but I'll but it's actually 23 seconds of data (there is silence at the start and end that probably got stripped by itunes when I ripped it to a .wav file.</div><div> </div><div>What I see is that put gets called post streaming if aplay or paplay are used to stream the file.  I'd like to see the pa_sink_input structure prior to streaming.</div><div> </div><div>The subscription lets me do this.</div><div> </div><div>I'd love to use _put but it comes in too late.</div><div> </div><div>From what Lennart said, I was under the impression that put would be called prior to streaming.</div><div> </div><div>Did I misunderstand this last part?</div><div> </div><div>Thanks</div><div> </div><div>Nick</div><div> </div><div> </div><div>Code for simple pulse module to log hook and subscription callbacks.</div><div> </div><div>  /*  * pulse module for stream routing to log hook calls for sink-inputs  * Nick Thompson  * 6/19/08  *  */ #include <pulsecore/config.h> #include <pulsecore/module.h> /* user data for the pulseaudio module, store this in init so that  * stuff we need can be accessed when we get callbacks  */ struct userdata {     /* cached references to pulse internals */     pa_core *core;     pa_module *module;     pa_subscription *subscription;     /* slots for our sink input hook functions */     pa_hook_slot *sink_input_new_hook_callback ;     pa_hook_slot *sink_input_fixate_hook_callback ;     pa_hook_slot *sink_input_put_hook_callback ;     pa_hook_slot *sink_input_unlink_hook_callback ;     pa_hook_slot *sink_input_unlink_post_hook_callback ;     pa_hook_slot *sink_input_move_hook_callback ;     pa_hook_slot *sink_input_move_post_callback ;     pa_hook_slot *sink_input_name_changed_hook_callback ;     pa_hook_slot *sink_input_state_changed_hook_callback ; }; static void subscribe_callback(pa_core *c, pa_subscription_event_type_t t, uint32_t idx, void *userdata); static pa_hook_result_t sink_input_new_hook(pa_core *c,                                             pa_sink_input_new_data *data,                                             struct userdata *u); static pa_hook_result_t sink_input_fixate_hook(pa_core *c,                                                pa_sink_input_new_data *data,                                                struct userdata *u); static pa_hook_result_t sink_input_put_hook(pa_core *c,                                             pa_sink_input *data,                                             struct userdata *u); static pa_hook_result_t sink_input_unlink_hook(pa_core *c,                                                pa_sink_input *data,                                                struct userdata *u); static pa_hook_result_t sink_input_unlink_post_hook(pa_core *c,                                                     pa_sink_input *data,                                                     struct userdata *u); static pa_hook_result_t sink_input_move_hook(pa_core *c,                                              pa_sink_input_move_hook_data *data,                                              struct userdata *u); static pa_hook_result_t sink_input_move_post(pa_core *c,                                              pa_sink_input *data,                                              struct userdata *u); static pa_hook_result_t sink_input_name_changed_hook(pa_core *c,                                                      pa_sink_input *data,                                                      struct userdata *u); static pa_hook_result_t sink_input_state_changed_hook(pa_core *c,                                                       pa_sink_input *data,                                                       struct userdata *u); static void log_time(void) ; PA_MODULE_AUTHOR("Nick Thompson") ; PA_MODULE_DESCRIPTION("Sniffer for sink input hook callbacks") ; PA_MODULE_VERSION(PACKAGE_VERSION) ; PA_MODULE_USAGE("Usage TBD" ) ; static void log_time(void) {     struct timeval itstime ;     struct timeval difftime ;     static struct timeval lasttime = {0,0};     int minutes;     int seconds;     int usecs ;     int delta;     pa_gettimeofday(&itstime);     difftime.tv_sec = itstime.tv_sec;     difftime.tv_usec = itstime.tv_usec;     pa_log("called at %d.%.06d",itstime.tv_sec,itstime.tv_usec);     if(0==(itstime.tv_sec-lasttime.tv_sec)) {         pa_log("   delta between last time called is %.06d (usecs)",                abs(itstime.tv_usec-lasttime.tv_usec));     } else {         pa_log("   delta between last time called is %02d(m) %02d(s) %.06d (usec)",                delta = abs(itstime.tv_sec-lasttime.tv_sec)/60,                abs(delta%60),                abs(itstime.tv_usec-lasttime.tv_usec));     }     lasttime.tv_sec = itstime.tv_sec;     lasttime.tv_usec = itstime.tv_usec;     pa_log(""); } static void subscribe_callback(pa_core *c, pa_subscription_event_type_t t, uint32_t idx, void *userdata) {     struct userdata *u =  userdata;     pa_sink_input *si = NULL;     pa_assert(c);     pa_assert(u);     pa_log("> subscribe_callback");     /* we are only interested in sink-input creation events */     if (t != (PA_SUBSCRIPTION_EVENT_SINK_INPUT)|PA_SUBSCRIPTION_EVENT_NEW) {         pa_log("< subscribe_callback - not a new sink input");         return;     } else {         if (!(si = pa_idxset_get_by_index(c->sink_inputs, idx))) {             pa_log("< subscribe_callback - can't get index");             return;         }     }     pa_log("subscribe_callback - new event received on sink-input with index %d",si->index);     pa_log("< subscribe_callback:");     log_time() ; } /* entry point for the module*/ int pa__init(pa_module* m) {     struct userdata *u = NULL;     int i;     pa_log("> pa__init");     pa_log("this version compiled - %s %s",__DATE__,__TIME__);     pa_assert(m);     u = pa_xnew(struct userdata, 1);     u->core = m->core;     u->module = m;     m->userdata = u;     /* install hooks to allow us to maange an internal, to this module,      * list of streams tied back to the originator sink of the stream      * this will be used to implement the policy in place.      */     u->sink_input_new_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_NEW],                                             (pa_hook_cb_t)sink_input_new_hook,                                             u);     u->sink_input_fixate_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_FIXATE],                                                         (pa_hook_cb_t)sink_input_fixate_hook,                                                         u);     u->sink_input_put_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_PUT],                                                      (pa_hook_cb_t)sink_input_put_hook,                                                      u);     u->sink_input_unlink_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_UNLINK],                                                         (pa_hook_cb_t)sink_input_unlink_hook,                                                         u);     u->sink_input_unlink_post_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_UNLINK_POST],                                                              (pa_hook_cb_t)sink_input_unlink_post_hook,                                                              u);     u->sink_input_move_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_MOVE],                                                       (pa_hook_cb_t)sink_input_move_hook,                                                       u);     u->sink_input_move_post_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_MOVE_POST],                                                       (pa_hook_cb_t)sink_input_move_post,                                                       u);     u->sink_input_name_changed_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_NAME_CHANGED],                                                               (pa_hook_cb_t)sink_input_name_changed_hook,                                                               u);     u->sink_input_state_changed_hook_callback = pa_hook_connect(&u->core->hooks[PA_CORE_HOOK_SINK_INPUT_STATE_CHANGED],                                                                (pa_hook_cb_t)sink_input_state_changed_hook,                                                                u);     /* install a subscription callback on the core */     u->subscription = pa_subscription_new(m->core, PA_SUBSCRIPTION_MASK_SINK_INPUT, subscribe_callback, u);     pa_log("< pa__init");     log_time() ;     return 0; fail:     pa_log("< pa__init - failure");     return -1; } static pa_hook_result_t sink_input_new_hook(pa_core *c,                                             pa_sink_input_new_data *data,                                             struct userdata *u){     pa_log("<  sink_input_new_hook");     log_time() ;     log_time() ;     pa_log("last message indicates approx overhead for log_time");         return PA_HOOK_OK; } static pa_hook_result_t sink_input_fixate_hook(pa_core *c,                                                pa_sink_input_new_data *data,                                                struct userdata *u){     pa_log("< sink_input_fixate_hook");     log_time() ;     return PA_HOOK_OK; } static pa_hook_result_t sink_input_put_hook(pa_core *c,                                             pa_sink_input *data,                                             struct userdata *u){     pa_log("< sink_input_put_hook");     log_time() ;     return PA_HOOK_OK; } static pa_hook_result_t sink_input_unlink_hook(pa_core *c,                                                pa_sink_input *data,                                                struct userdata *u){     pa_log("< sink_input_unlink_hook");     log_time() ;     return PA_HOOK_OK; } static pa_hook_result_t sink_input_unlink_post_hook(pa_core *c,                                                     pa_sink_input *data,                                                     struct userdata *u){     pa_log("< sink_input_unlink_post_hook");     log_time() ;     return PA_HOOK_OK; } static pa_hook_result_t sink_input_move_hook(pa_core *c,                                              pa_sink_input_move_hook_data *data,                                              struct userdata *u){     pa_log("< sink_input_move_hook");     return PA_HOOK_OK; } static pa_hook_result_t sink_input_move_post(pa_core *c,                                              pa_sink_input *data,                                              struct userdata *u){     pa_log("< sink_input_move_post");     log_time() ;     return PA_HOOK_OK; } static pa_hook_result_t sink_input_name_changed_hook(pa_core *c,                                                      pa_sink_input *data,                                                      struct userdata *u){     pa_log("< sink_input_name_changed_hook");     log_time() ;     return PA_HOOK_OK; } static pa_hook_result_t sink_input_state_changed_hook(pa_core *c,                                                       pa_sink_input *data,                                                       struct userdata *u){     pa_log("< sink_input_state_changed_hook");     log_time() ;     return PA_HOOK_OK; } /* exit and cleanup */ void pa__done(pa_module *m) {     struct userdata *u ;     pa_log("> pa__done");     pa_assert(m) ;     if (!(u = m->userdata))         return;     if(u->sink_input_new_hook_callback )         pa_hook_slot_free(u->sink_input_new_hook_callback) ;     if(u->sink_input_fixate_hook_callback )         pa_hook_slot_free(u->sink_input_fixate_hook_callback) ;     if(u->sink_input_put_hook_callback )         pa_hook_slot_free(u->sink_input_put_hook_callback) ;     if(u->sink_input_unlink_hook_callback )         pa_hook_slot_free(u->sink_input_unlink_hook_callback) ;     if(u->sink_input_unlink_post_hook_callback )         pa_hook_slot_free(u->sink_input_unlink_post_hook_callback) ;     if(u->sink_input_move_hook_callback )         pa_hook_slot_free(u->sink_input_move_hook_callback) ;     if(u->sink_input_move_post_callback )         pa_hook_slot_free(u->sink_input_move_post_callback) ;     if(u->sink_input_name_changed_hook_callback )         pa_hook_slot_free(u->sink_input_name_changed_hook_callback) ;     if(u->sink_input_state_changed_hook_callback )         pa_hook_slot_free(u->sink_input_state_changed_hook_callback) ;     pa_xfree(u);     pa_log("< pa__done");     log_time() ; }  </div></div></div></body></html>