[watzen]

HI,

I've created my first script and I was struck by the time it took to fetch a single webpage. Until I realized that it was only the first fetch for that script-session that was slow.

Further investigation in the xbmc.log (running the nightly from 24/2-2011) revealed that the most probable culprit is the lines marked in bold below:

Code:

00:02:11 T:4308 M:2341310464  NOTICE: start
00:02:11 T:4308 M:2341310464  NOTICE: one
00:02:11 T:4308 M:2341298176   DEBUG: Win32DllLoader::Load(ADVAPI32.DLL)
00:02:11 T:4308 M:2341298176   DEBUG: Win32DllLoader::Load(KERNEL32.DLL)
00:02:12 T:4308 M:2341298176   DEBUG: Win32DllLoader::Load(USER32.DLL)
00:02:12 T:4308 M:2341298176   DEBUG: Win32DllLoader::Load(NETAPI32.DLL)
00:02:12 T:4308 M:2341298176   DEBUG: FreeLibrary(NETAPI32.DLL) -> 078D2B70
00:02:12 T:4308 M:2341298176   DEBUG: Win32DllLoader::Unload NETAPI32.DLL
00:02:12 T:4308 M:2341298176   DEBUG: FreeLibrary(ADVAPI32.DLL) -> 078D2B30
00:02:12 T:4308 M:2341298176   DEBUG: Win32DllLoader::Unload ADVAPI32.DLL
00:02:12 T:4308 M:2341298176   DEBUG: FreeLibrary(USER32.DLL) -> 078D2BF0
00:02:12 T:4308 M:2341298176   DEBUG: Win32DllLoader::Unload USER32.DLL
[b]00:02:12 T:700 M:2340888576   ERROR: CRemoteControl::Connect - failed to connect[/b]
00:02:12 T:3720 M:2341867520   DEBUG: ------ Window Init (DialogBusy.xml) ------
00:02:13 T:2440 M:2339745792    INFO: Loading skin file: DialogProgress.xml
00:02:13 T:2440 M:2340925440   DEBUG: DialogProgress::StartModal called
00:02:13 T:2440 M:2339749888   DEBUG: ------ Window Init (DialogProgress.xml) ------
00:02:13 T:3720 M:2340958208   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
[b]00:02:15 T:700 M:2341994496   DEBUG: CRemoteControl::Connect - connecting to: ::1:24000 ...
00:02:16 T:700 M:2340864000   DEBUG: CRemoteControl::Connect - connecting to: 127.0.0.1:24000 ...
00:02:17 T:700 M:2340855808   ERROR: CRemoteControl::Connect - failed to connect
00:02:20 T:700 M:2340917248   DEBUG: CRemoteControl::Connect - connecting to: ::1:24000 ...[/b]
00:02:20 T:4308 M:2340917248   DEBUG: FreeLibrary(KERNEL32.DLL) -> 078D2BB0
00:02:20 T:4308 M:2340917248   DEBUG: Win32DllLoader::Unload KERNEL32.DLL
00:02:20 T:4308 M:2340777984  NOTICE: two
[b]00:02:21 T:700 M:2340757504   DEBUG: CRemoteControl::Connect - connecting to: 127.0.0.1:24000 ...[/b]
00:02:21 T:4308 M:2340802560  NOTICE: three
00:02:21 T:4308 M:2340798464  NOTICE: four
[b]00:02:22 T:700 M:2340798464   ERROR: CRemoteControl::Connect - failed to connect[/b]
00:02:22 T:4308 M:2340786176    INFO: Scriptresult: Success

I've come to the understanding that it regards the IRServerSuite. But I don't know why it would try to connect to it by default. I haven't enabled it and don't use it. Anyone else experienced this?

(trac ticket: 11260)

[jmarshall]

That is not the problem at all - as you can see from the log that is coming from a separate thread.

Rather, the problem is the loading of the windows dll's used for net access (everything in thread 4308).

Please update your ticket accordingly.

IIRC there was mentions of what this is and why it's done somewhere in the past - try searching trac perhaps.

[watzen]

That is not the problem at all - as you can see from the log that is coming from a separate thread.

Rather, the problem is the loading of the windows dll's used for net access (everything in thread 4308).

Please update your ticket accordingly.

IIRC there was mentions of what this is and why it's done somewhere in the past - try searching trac perhaps.

ok, my bad then. I've added a comment to the ticket, since I can't change it.

I couldn't find any references to kernel32.dll och user32.dll that regards the same problem. So the question still stands for me, is it normal for it to take 10 seconds to load some dll's?

P.S. btw, the loading of dll's was my first thought, then bobo1on1 couldn't believe that so he got my thoughts on this other track

/watz

[watzen]

Hi, I'm bumping this a bit.

I've got a new angle. maybe there is some better way of handling this piece of code:

Code:

cj = cookielib.LWPCookieJar()
    opener = urllib2.build_opener(urllib2.HTTPCookieProcessor(cj))
    print 'start'
    urllib2.install_opener(opener)
    print 'one'
    resp = opener.open('https://hdbits.org/login.php')
    print 'two'    
    svar3 = resp.read()
    resp.close()
    lols = re.compile('<input type="hidden" name="lol" value="(.+?)" />').findall(svar3)
    if len(lols) == 1:
        lol = str(lols[0])
        data = urllib.urlencode({'uname':username,'password':user_password,'lol':lol})
        resp = opener.open('https://hdbits.org/takelogon.php', data)
        svar1 = resp.read()
        resp.close()

It is this little piece of code that takes a long time. And it is not because the server/connection is slow. Since consecutive request to the site goes fast.