TC3811 takes *hours* to verify for VSS changes

Howdy,

Yes, unfortunately I'm stuck with VSS6.0 at the current place. Pity me :-).
Moving to the technical issue now:

I installed TC 3811 last week on a Win2003/2.4GHz/2GB RAM (same as our current
CruiseControl machine). The project has about 8000 Java files and about 3000
of other files in various subdirectories. CC takes a few minutes to check
for changes. TC took 4h50' (with CC stopped so nothing was using the machine).
I sniffed the traffic and there was traffic going on(SMB traffic to the VSS
server). At the end of the five hours, no change was found. I looked in the
logs but nothing was obviously useful.


Is there a debug setting of your own SS client (whose instances named like
TC-TFS-NATIVE-1174314727593.exe are created in TeamCity\Temp?).


I installed 3914 this morning and there seems to be a problem with the agent
communication, "Status Disconnected (Ping failed), " (the service is up,
the ports are correct) so I have yet to get to the stage where I can try
with the latest build.

Thanks,
RP


15 comments
Comment actions Permalink

3.5 hours and going.... (log below).

Also weird, the 2 timestamps (most likely start/end) are the same, perhaps
it's trying to calculate the instantaneous rate of change. The commit rate
first derivative? :)

Any idea how to investigate it further?



INFO - .web.servlet.DispatcherServlet - FrameworkServlet
'buildServer': initialization completed in 2078 ms
INFO - .web.servlet.DispatcherServlet - Servlet
'buildServer' configured successfully
INFO - brains.buildServer.NetworkUtil - Found
Network Interfaces:
INFO - jetbrains.buildServer.Server - Upgrade
of agent dwcc01 has been started
INFO - jetbrains.buildServer.Server - Agent
dwcc01 has been registered with id 1 currently runnung build -1
INFO - SimpleCommandLineProcessRunner - Start
process name: e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe e:\TeamCity\temp\TC-VSS-1-.output
e:\TeamCity\temp\TC-VSS-2-.error "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
/login:USER /pwd:PASSWORD connection $/OURPRODUCT
INFO - ers.vcs.vss.FilesCleanupThread - e:\TeamCity\temp\TC-VSS-1-.output

INFO - ers.vcs.vss.FilesCleanupThread - e:\TeamCity\temp\TC-VSS-2-.error

INFO - ildTriggers.vcs.vss.VssSupport - version
from 1174413047004 to 1174413077004
INFO - SimpleCommandLineProcessRunner - Start
process name: e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe e:\TeamCity\temp\TC-VSS-3-.output
e:\TeamCity\temp\TC-VSS-4-.error "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
/login:USER /pwd:PASSWORD history $/OURPRODUCT 1174413047004 1174413077004
INFO - activities.log.ActivitiesLog - Configuration
added to queue; configurationName=continuous build; requestor=admin
INFO - activities.log.ActivitiesLog - Build
started; buildId=1
INFO - activities.log.ActivitiesLog - Configuration
removed from queue; configurationName=continuous build
INFO - rver.serverSide.VersionChecker - Checking
for new version...
INFO - rver.serverSide.VersionChecker - New version
is not available

Howdy,

Yes, unfortunately I'm stuck with VSS6.0 at the current place. Pity me
:-). Moving to the technical issue now:

I installed TC 3811 last week on a Win2003/2.4GHz/2GB RAM (same as our
current CruiseControl machine). The project has about 8000 Java files
and about 3000 of other files in various subdirectories. CC takes a
few minutes to check for changes. TC took 4h50' (with CC stopped so
nothing was using the machine). I sniffed the traffic and there was
traffic going on(SMB traffic to the VSS server). At the end of the
five hours, no change was found. I looked in the logs but nothing was
obviously useful.

Is there a debug setting of your own SS client (whose instances named
like TC-TFS-NATIVE-1174314727593.exe are created in TeamCity\Temp?).

I installed 3914 this morning and there seems to be a problem with the
agent communication, "Status Disconnected (Ping failed), " (the
service is up, the ports are correct) so I have yet to get to the
stage where I can try with the latest build.

Thanks,
RP



0
Comment actions Permalink

Hello Raz,

What version of VSS do you use?

Did changes analisys takes a lot of time at every start? Or only at the
first?
Do you have 'Clean all files before build' option set for the build?
How long does it takes to build patch (first lines of the build log)


--
Eugene Petrenko
JetBrains, Inc
http://www.jetbrains.com
"Develop with pleasure!"

3.5 hours and going.... (log below).

Also weird, the 2 timestamps (most likely start/end) are the same,
perhaps it's trying to calculate the instantaneous rate of change. The
commit rate first derivative? :)

Any idea how to investigate it further?

INFO - .web.servlet.DispatcherServlet -
FrameworkServlet 'buildServer': initialization completed in 2078 ms
INFO - .web.servlet.DispatcherServlet -
Servlet 'buildServer' configured successfully [2007-03-20
13:47:47,914] INFO - brains.buildServer.NetworkUtil - Found Network
Interfaces: INFO -
jetbrains.buildServer.Server - Upgrade of agent dwcc01 has been
started INFO -
jetbrains.buildServer.Server - Agent dwcc01 has been registered with
id 1 currently runnung build -1 INFO -
SimpleCommandLineProcessRunner - Start process name:
e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe
e:\TeamCity\temp\TC-VSS-1-.output e:\TeamCity\temp\TC-VSS-2-.error
"C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini" /login:USER
/pwd:PASSWORD connection $/OURPRODUCT INFO
- ers.vcs.vss.FilesCleanupThread - e:\TeamCity\temp\TC-VSS-1-.output

INFO - ers.vcs.vss.FilesCleanupThread -
e:\TeamCity\temp\TC-VSS-2-.error

INFO - ildTriggers.vcs.vss.VssSupport -
version from 1174413047004 to 1174413077004
INFO - SimpleCommandLineProcessRunner - Start process name:
e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe
e:\TeamCity\temp\TC-VSS-3-.output e:\TeamCity\temp\TC-VSS-4-.error
"C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini" /login:USER
/pwd:PASSWORD history $/OURPRODUCT 1174413047004 1174413077004
INFO - activities.log.ActivitiesLog -
Configuration added to queue; configurationName=continuous build;
requestor=admin INFO -
activities.log.ActivitiesLog - Build started; buildId=1 [2007-03-20
13:59:41,647] INFO - activities.log.ActivitiesLog - Configuration
removed from queue; configurationName=continuous build [2007-03-20
15:47:46,931] INFO - rver.serverSide.VersionChecker - Checking for
new version... INFO -
rver.serverSide.VersionChecker - New version is not available

>> Howdy,
>>
>> Yes, unfortunately I'm stuck with VSS6.0 at the current place. Pity
>> me :-). Moving to the technical issue now:
>>
>> I installed TC 3811 last week on a Win2003/2.4GHz/2GB RAM (same as
>> our current CruiseControl machine). The project has about 8000 Java
>> files and about 3000 of other files in various subdirectories. CC
>> takes a few minutes to check for changes. TC took 4h50' (with CC
>> stopped so nothing was using the machine). I sniffed the traffic and
>> there was traffic going on(SMB traffic to the VSS server). At the end
>> of the five hours, no change was found. I looked in the logs but
>> nothing was obviously useful.
>>
>> Is there a debug setting of your own SS client (whose instances named
>> like TC-TFS-NATIVE-1174314727593.exe are created in TeamCity\Temp?).
>>
>> I installed 3914 this morning and there seems to be a problem with
>> the agent communication, "Status Disconnected (Ping failed), " (the
>> service is up, the ports are correct) so I have yet to get to the
>> stage where I can try with the latest build.
>>
>> Thanks,
>> RP


0
Comment actions Permalink

Hello Eugene,

Thanks for the reply, I started to fear we'll be stuck with Cruise.

Hello Raz,

What version of VSS do you use?


server: 6.0d (Build 9848)

Did changes analisys takes a lot of time at every start? Or only at the

first?

So far, all attempts have been the first after restart ( I stopped TC1.2
once to install the 3811 EAP, then did the same for 3914 EAP).

Yesterday's attempt took even longer: Checking for changes (6h:49m:49s)

Do you have 'Clean all files before build' option set for the
build?


Yes (I'll try now without).

How long does it takes to build patch (first lines of the build log)


See below.

INFO - rver.agent.impl.BuildAgentImpl - Start
build agent
INFO - rver.agent.impl.BuildAgentImpl - Start
agent Web server on port 9090
INFO - rver.agent.impl.BuildAgentImpl - Agent
Web server started
INFO - rver.agent.impl.BuildAgentImpl - Build
agent started
INFO - brains.buildServer.NetworkUtil - Found
Network Interfaces:
INFO - r.agent.impl.ServerXmlRpcProxy - Registering
on build server: dwcc01 10.64.0.134 9090 [Command Line, Ant, MSBuild, sln2005,
Duplicator, Inspection, Ipr, Maven2]
INFO - r.agent.impl.ServerXmlRpcProxy - Registered:
1
INFO - r.agent.impl.ServerXmlRpcProxy - Make
sure this agent is enabled in the server web UI.
INFO - rver.agent.impl.BuildAgentImpl - Found
runner Ant for
[BuildInfo {teamcity.checkout.on.agent=false, idea.build.server.build.id=1,
teamcity.checkout.on.server=true, teamcity.clean.build=true, teamcity.execution.timeout=0,
teamcity.run.type=Ant, teamcity.buildType.id=bt1, teamcity.project.name=OURPROJECT,
teamcity.is.personal=false}]

INFO - rver.agent.impl.BuildAgentImpl - Getting
sources...
INFO - rver.agent.impl.BuildAgentImpl - Requesting
patch from server, cleanPatch=true
INFO - rver.agent.impl.BuildAgentImpl - Copying
patch to temp file...
INFO - rver.agent.impl.BuildAgentImpl - Patch
downloaded
INFO - Server.vcs.patches.PatcherImpl - Clearing
working directory e:\TeamCity\buildAgent\work\Server\OURPROJECT
INFO - rver.agent.impl.BuildAgentImpl - Sources
loaded for 31556 seconds
INFO - rver.agent.impl.BuildAgentImpl - Patch
applied successfully

>> 3.5 hours and going.... (log below).
>>
>> Also weird, the 2 timestamps (most likely start/end) are the same,
>> perhaps it's trying to calculate the instantaneous rate of change.
>> The commit rate first derivative? :)
>>
>> Any idea how to investigate it further?
>>
>> INFO - .web.servlet.DispatcherServlet -
>> FrameworkServlet 'buildServer': initialization completed in 2078 ms
>> INFO - .web.servlet.DispatcherServlet -
>> Servlet 'buildServer' configured successfully [2007-03-20
>> 13:47:47,914] INFO - brains.buildServer.NetworkUtil - Found Network
>> Interfaces: INFO -
>> jetbrains.buildServer.Server - Upgrade of agent dwcc01 has been
>> started INFO -
>> jetbrains.buildServer.Server - Agent dwcc01 has been registered with
>> id 1 currently runnung build -1 INFO -
>> SimpleCommandLineProcessRunner - Start process name:
>> e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe
>> e:\TeamCity\temp\TC-VSS-1-.output e:\TeamCity\temp\TC-VSS-2-.error
>> "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
>> /login:USER /pwd:PASSWORD connection $/OURPRODUCT [2007-03-20
>> 13:50:19,645] INFO - ers.vcs.vss.FilesCleanupThread -
>> e:\TeamCity\temp\TC-VSS-1-.output
>>
>> INFO - ers.vcs.vss.FilesCleanupThread -
>> e:\TeamCity\temp\TC-VSS-2-.error
>>
>> INFO - ildTriggers.vcs.vss.VssSupport -
>> version from 1174413047004 to 1174413077004
>> INFO - SimpleCommandLineProcessRunner - Start process name:
>> e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe
>> e:\TeamCity\temp\TC-VSS-3-.output e:\TeamCity\temp\TC-VSS-4-.error
>> "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
>> /login:USER /pwd:PASSWORD history $/OURPRODUCT 1174413047004
>> 1174413077004 INFO -
>> activities.log.ActivitiesLog - Configuration added to queue;
>> configurationName=continuous build; requestor=admin [2007-03-20
>> 13:59:41,631] INFO - activities.log.ActivitiesLog - Build started;
>> buildId=1 INFO -
>> activities.log.ActivitiesLog - Configuration removed from queue;
>> configurationName=continuous build INFO -
>> rver.serverSide.VersionChecker - Checking for new version...
>> INFO - rver.serverSide.VersionChecker -
>> New version is not available
>>
>>> Howdy,
>>>
>>> Yes, unfortunately I'm stuck with VSS6.0 at the current place. Pity
>>> me :-). Moving to the technical issue now:
>>>
>>> I installed TC 3811 last week on a Win2003/2.4GHz/2GB RAM (same as
>>> our current CruiseControl machine). The project has about 8000 Java
>>> files and about 3000 of other files in various subdirectories. CC
>>> takes a few minutes to check for changes. TC took 4h50' (with CC
>>> stopped so nothing was using the machine). I sniffed the traffic and
>>> there was traffic going on(SMB traffic to the VSS server). At the
>>> end of the five hours, no change was found. I looked in the logs but
>>> nothing was obviously useful.
>>>
>>> Is there a debug setting of your own SS client (whose instances
>>> named like TC-TFS-NATIVE-1174314727593.exe are created in
>>> TeamCity\Temp?).
>>>
>>> I installed 3914 this morning and there seems to be a problem with
>>> the agent communication, "Status Disconnected (Ping failed), " (the
>>> service is up, the ports are correct) so I have yet to get to the
>>> stage where I can try with the latest build.
>>>
>>> Thanks,
>>> RP


0
Comment actions Permalink

Did changes analisys takes a lot of time at every start? Or only at the

first?

Do you have 'Clean all files before build' option set for the build?


a quick update: with 'clean all files' disabled, the estimate is the same:

Started: 21 Mar 11:17 Stop build
Estimated time: 8h:23m:36s


Is there a debug flag for your VSS client to dump what it's actually doing?
If not, I'll log the traffic with a sniffer.


0
Comment actions Permalink

Hello Raz,

That whould be nice to have a look to log from TC-VSS-NATIVE.exe.
Unfortunately there is no debug version for that binary. I can share you
sources of that utility for debug. (That is VS2003 solution)

It seems that performance problems are connected with the call to
IVSSItem::get_Versions

BTW. Can you share your VSS repository for us?

Build estimate time is predicted by server according to build behaviour.
TC VSS
integration plugin is not queried for any predictions.

Thanks!

--
Eugene Petrenko
JetBrains, Inc
http://www.jetbrains.com
"Develop with pleasure!"

>> Did changes analisys takes a lot of time at every start? Or only at
>> the
>>

first?

>> Do you have 'Clean all files before build' option set for the build?
>>

a quick update: with 'clean all files' disabled, the estimate is the
same:

Started: 21 Mar 11:17 Stop build Estimated time: 8h:23m:36s

Is there a debug flag for your VSS client to dump what it's actually
doing? If not, I'll log the traffic with a sniffer.



0
Comment actions Permalink

Hello Eugene,

That whould be nice to have a look to log from TC-VSS-NATIVE.exe.


Which specific file would that be? I looked in \TeamCity\logs and \TeamCity\buildAgent\logs,
but they don't contain detailed info about what TC-VSS-NATIVE is doing "inside",
just about the overall process.

\TeamCity\temp\TC-VSS-29-.output contains:

]]>

Unfortunately there is no debug version for that binary. I can share
you sources of that utility for debug. (That is VS2003 solution)


Not sure if we have VS2003 around (it's a Java shop). I think it's a lot
faster for you to add a "-debug" flag to dump some relevant info.

It seems that performance problems are connected with the call to
IVSSItem::get_Versions


Indeed. I sniffed the traffic and it's weird (sniffer summary below). The
traffic repeats the sequence below, with different files. It's SMB traffic
as VSS (in the wisdom of its creators) is using the Windows sharing protocol
for its traffic. The weird part is the contents of the TCP segments, though:
it sometimes contains fragments of code (diffs??) or I see references to
older branches/locations in the repository. Instead of seeing $/CURRENTPROJECT
I see $/REALLYOLDPROJECT or $/OLDPROJECT. Perhaps these are internal references
to the original version?
It's strange, though, that I see fragments of code, it's as if TC-VSS-NATIVE
not only checks for timestamps to detect changes, but retrieves the differences
as well (for later display, I can see the reason and for other repositories
it may work well).

The other possibility is that TC-VSS-NATIVE parses the entire VSS repository,
not just the intended project (this would be a bug). There are a few dozen
projects in the tree now.


No. Time Source Destination Protocol
Info
78 12:11:24.132304 teamcity vss SMB NT Create
AndX Request, Path: \data\i\iyzgaaaa
79 12:11:24.133057 vss teamcity SMB NT Create
AndX Response, FID: 0x43a3
80 12:11:24.133311 teamcity vss SMB Trans2
Request, QUERY_FILE_INFO, FID: 0x43a3, Query File Internal Info
81 12:11:24.133578 vss teamcity SMB Trans2
Response, QUERY_FILE_INFO
82 12:11:24.133762 teamcity vss SMB Read
AndX Request, FID: 0x43a3, 4096 bytes at offset 0
83 12:11:24.134544 vss teamcity TCP [TCP
segment of a reassembled PDU]
84 12:11:24.134659 vss teamcity TCP [TCP
segment of a reassembled PDU]
85 12:11:24.134690 teamcity vss TCP 3746

microsoft-ds Seq=2326 Ack=16583 Win=65535 Len=0

86 12:11:24.134765 vss teamcity SMB Read
AndX Response, FID: 0x43a3, 4096 bytes
87 12:11:24.146842 teamcity vss SMB Read
AndX Request, FID: 0x43a3, 3809 bytes at offset 12288
88 12:11:24.147576 vss teamcity TCP [TCP
segment of a reassembled PDU]
89 12:11:24.147696 vss teamcity TCP [TCP
segment of a reassembled PDU]
90 12:11:24.147726 teamcity vss TCP 3746

microsoft-ds Seq=2389 Ack=20743 Win=65535 Len=0

91 12:11:24.147778 vss teamcity SMB Read
AndX Response, FID: 0x43a3, 3809 bytes



Let me know how I can help further.

Thanks,
Raz

BTW. Can you share your VSS repository for us?


Most likely the management will say no (for all the usual reasons).


0
Comment actions Permalink

Hello Raz,

I've prepared a loggin version of TeamCity integration for you.
It will create files in the temp directory with names ending with '.logs.txt'

To set up that file please do the following:
- shutdown teamcity webserver
- put all files from the archive to the
]]>\webapps\ROOT\WEB-INF\classes\bin
- Start teamcity webserver.

Now TeamCity will work with VSS with debugging switched on. To switch off debugging, please,
copy old file back to the folder.

What speed does network between TC server and VSS operate?

Do you have VSS journal option switched on?

Thanks!

--
Eugene Petrenko
JetBrains, Inc
http://www.jetbrains.com
"Develop with pleasure!"

Hello Eugene,

>
>> That whould be nice to have a look to log from TC-VSS-NATIVE.exe.
>>

Which specific file would that be? I looked in \TeamCity\logs and
\TeamCity\buildAgent\logs, but they don't contain detailed info about
what TC-VSS-NATIVE is doing "inside", just about the overall process.

>

\TeamCity\temp\TC-VSS-29-.output contains:

>

<?xml version="1.0"?><history from="20.03.2007 19:33:05"
to="21.03.2007 15:17:21">

>
>> Unfortunately there is no debug version for that binary. I can share
>> you sources of that utility for debug. (That is VS2003 solution)
>>

Not sure if we have VS2003 around (it's a Java shop). I think it's a
lot faster for you to add a "-debug" flag to dump some relevant info.

>
>> It seems that performance problems are connected with the call to
>> IVSSItem::get_Versions
>>

Indeed. I sniffed the traffic and it's weird (sniffer summary below).
The
traffic repeats the sequence below, with different files. It's SMB
traffic
as VSS (in the wisdom of its creators) is using the Windows sharing
protocol
for its traffic. The weird part is the contents of the TCP segments,
though:
it sometimes contains fragments of code (diffs??) or I see references
to
older branches/locations in the repository. Instead of seeing
$/CURRENTPROJECT
I see $/REALLYOLDPROJECT or $/OLDPROJECT. Perhaps these are internal
references
to the original version?
It's strange, though, that I see fragments of code, it's as if
TC-VSS-NATIVE
not only checks for timestamps to detect changes, but retrieves the
differences
as well (for later display, I can see the reason and for other
repositories
it may work well).
The other possibility is that TC-VSS-NATIVE parses the entire VSS
repository, not just the intended project (this would be a bug). There
are a few dozen projects in the tree now.

>

No. Time Source Destination
Protocol
Info
78 12:11:24.132304 teamcity vss SMB NT
Create
AndX Request, Path: \data\i\iyzgaaaa
79 12:11:24.133057 vss teamcity SMB NT
Create
AndX Response, FID: 0x43a3
80 12:11:24.133311 teamcity vss SMB
Trans2
Request, QUERY_FILE_INFO, FID: 0x43a3, Query File Internal Info
81 12:11:24.133578 vss teamcity SMB
Trans2
Response, QUERY_FILE_INFO
82 12:11:24.133762 teamcity vss SMB
Read
AndX Request, FID: 0x43a3, 4096 bytes at offset 0
83 12:11:24.134544 vss teamcity TCP
[TCP
segment of a reassembled PDU]
84 12:11:24.134659 vss teamcity TCP
[TCP
segment of a reassembled PDU]
85 12:11:24.134690 teamcity vss TCP
3746

>> microsoft-ds Seq#26 Ack 583 Wine535 Len=0
>>

86 12:11:24.134765 vss teamcity SMB
Read
AndX Response, FID: 0x43a3, 4096 bytes
87 12:11:24.146842 teamcity vss SMB
Read
AndX Request, FID: 0x43a3, 3809 bytes at offset 12288
88 12:11:24.147576 vss teamcity TCP
[TCP
segment of a reassembled PDU]
89 12:11:24.147696 vss teamcity TCP
[TCP
segment of a reassembled PDU]
90 12:11:24.147726 teamcity vss TCP
3746

>> microsoft-ds Seq#89 Ack 743 Wine535 Len=0
>>

91 12:11:24.147778 vss teamcity SMB
Read
AndX Response, FID: 0x43a3, 3809 bytes
Let me know how I can help further.

>

Thanks,
Raz

>> BTW. Can you share your VSS repository for us?
>>

Most likely the management will say no (for all the usual reasons).

>

Attachment not added (general error): "vss-native-2007-03-21.zip"

0
Comment actions Permalink

Hello Eugene,

I've prepared a loggin version of TeamCity integration for you.


Thanks, I'll try it now. The current status:

: Checking for changes (2h:17m:41s)
: Building in e:\TeamCity\buildAgent\work\Server\OURPROJECT
: Getting project sources (running for 1h:51m:29s)

Checking for changes is indeed faster without 'clean all files' on. Of course,
it's not fast in absolute terms, just a few times faster than the other case.

What speed does network between TC server and VSS operate?


Ethernet 100Mbps.


Do you have VSS journal option switched on?


No.


I'll post another message with the output of the logging native client.

Thanks!
Raz


0
Comment actions Permalink

Hello Eugene,

Additional info before switching to the debug version:


There were 2 running instances of TC-VSS-NATIVE, launched with parameters
as below (taken with ProcessExplorer)/ Both were consuming CPU and were
actively talking with the VSS server. I had forgotten to set "Number of
simultaneously running builds " to 1, I'll do it for the next attempt. BTW,
stopping the TeamCity services did not kill those processes, they had to
be killed manually.



Shouldn't history checking be disabled once a build is started? I'm only
interested in one build at a time now.


e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe e:\TeamCity\temp\TC-VSS-35-.output
e:\TeamCity\temp\TC-VSS-36-.error "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
patch $/OURPROJECT e:\TeamCity\temp\ 0 1174419184970
e:\TeamCity\temp\TC-VSS-NATIVE-1174412864758.exe e:\TeamCity\temp\TC-VSS-37-.output
e:\TeamCity\temp\TC-VSS-38-.error "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
history $/OURPROJECT 1174419184970 1174503997075

The output of the 'patch' instance was actively growing and had lines like
below

]]>

There were about 2200 TC-VSS-TEMP-nnnn.vss files in \TeamCity\temp, they
appear to be the normal files of the release.

Another clarification: I don't have any build trigger set yet (mainly to
control when TC runs).

I'll be back :)


0
Comment actions Permalink

Hello Eugene,

I've prepared a loggin version of TeamCity integration for you.
It will create files in the temp directory with names ending with
'.logs.txt'


The results so far and a possible cause of the problem towards the end of
the message.

Upon starting the build, TC-VSS-1-.output.logs.txt was created and it contains
the following. 15 minutes have passed since starting the build, nothing else
has been added to the log. By monitoring file/network, I can see that TC-VSS-NATIVE
is actively working with the VSS server, though.

Use VSS 6.0 SSAPI
History request from: 20.03.2007 19:33:05, to: 21.03.2007
20:13:11
History request for path: $/OURPROJECT
History request Root item: $/OURPROJECT,
HistoryRequest: visitNode spec=$/OURPROJECT
History request: VisitV spec $/OURPROJECT version 08.03.2007
16:29:54
HistoryRequest: visitNode finish $/OURPROJECT
History request: Item $/OURPROJECT, before v=6, after
v=6
ShouldVisitSubtree for $/OURPROJECT
Start get_Versions(VSSFLAG_RECURSYES, &versions)
Done get_Versions(VSSFLAG_RECURSYES, &versions)

teamcity.log:

INFO - ildTriggers.vcs.vss.VssSupport - version
from 1174419184970 to 1174507990606
INFO - SimpleCommandLineProcessRunner - Start
process name: e:\TeamCity\temp\TC-VSS-NATIVE-1174507987778.exe e:\TeamCity\temp\TC-VSS-1-.output
e:\TeamCity\temp\TC-VSS-2-.error "C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini"
history $/OURPROJECT 1174419184970 1174507990606
INFO - jetbrains.buildServer.Server - Agent
dwcc01 has been registered with id 1 currently runnung build -1
INFO - activities.log.ActivitiesLog - Configuration
added to queue; configurationName=continuous build; requestor=admin
INFO - activities.log.ActivitiesLog - Build
started; buildId=3
INFO - activities.log.ActivitiesLog - Configuration
removed from queue; configurationName=continuous build

Filemon dump taken 20' after starting the build shows the TC-VSS-NATIVE going
through the files.

1 4:33:09 PM TC-VSS-NATIVE-1:21040 OPEN
VSSSERVER\VSS\data\e\evboaaaa SUCCESS
Options: Open Access: Read
2 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION
VSSSERVER\VSS\data\e\evboaaaa
SUCCESS FileFsDeviceInformation
3 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION
VSSSERVER\VSS\data\e\evboaaaa
SUCCESS FileStandardInformation
4 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\e\evboaaaa
SUCCESS Offset: 0 Length: 1024
5 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\e\evboaaaa
SUCCESS Offset: 0 Length: 4096
6 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\e\evboaaaa SUCCESS
Offset: 1024 Length: 1024
7 4:33:09 PM TC-VSS-NATIVE-1:21040 OPEN
VSSSERVER\VSS\data\c\cqbnaaaa SUCCESS
Options: Open Access: Read
8 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION
VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS FileFsDeviceInformation
9 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION
VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS FileStandardInformation
10 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS Offset: 0 Length: 1024
11 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS Offset: 0 Length: 4096
12 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS Offset: 1024 Length: 1024
13 4:33:09 PM TC-VSS-NATIVE-1:21040 CLOSE
VSSSERVER\VSS\data\e\evboaaaa
SUCCESS
14 4:33:09 PM TC-VSS-NATIVE-1:21040 OPEN
VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Options: Open Access: Read
15 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION
VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS FileFsDeviceInformation
16 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION
VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS FileStandardInformation
17 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Offset: 0 Length: 1024
18 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Offset: 0 Length: 4096
19 4:33:09 PM TC-VSS-NATIVE-1:21040 READ
VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Offset: 1024 Length: 1024
20 4:33:09 PM TC-VSS-NATIVE-1:21040 CLOSE
VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS
21 4:33:09 PM TC-VSS-NATIVE-1:21040 CLOSE
VSSSERVER\VSS\data\r\rghmaaaa
SUCCESS


I looked in one of the files it was searching (like
VSSSERVER\VSS\data\m\mghmaaaa).
VSS seems to have 2 files/real file, one is a wrapper with the real filename
and other metadata, the second one with the same name and extension like
a or b (e.g. mghmaaaa.a) is the latest version.


However, this particular file is NOT under $/OURPROJECT but under a different
one (like $/REALLYOLDPROJECT). There is no file with this name for the version
I set up TC to build. So, I speculate the native client is parsing the entire
VSS directory, not only $/OURPROJECT. It may ignore those other projects
afterwards, but it still reads information about them and thus adding to
the processing time.

HTH,
Raz


0
Comment actions Permalink

Raz, you may watch
http://www.jetbrains.net/jira/browse/TW-2118
for the status of the problem.

Thanks,
KIR

0
Comment actions Permalink

Hello Kirill,

Raz, you may watch
http://www.jetbrains.net/jira/browse/TW-2118
for the status of the problem.
Thanks,
KIR


An update with the logs so far. I did a 'dir' and augmented it to the right
with the main "contents" of the file, i.e. the relevant line indicating what
the rest of the stuff contains. That line is extracted from the log.

Omea may wrap the lines when posting, please unwrap.

HTH,
Raz


03/21/2007 04:13p 174 TC-VSS-1-.output 03/21/2007 07:14p 439,704 TC-VSS-1-.output.logs.txt History request from: 20.03.2007 19:33:05, to: 21.03.2007 20:13:11 03/22/2007 01:14a 1,758 TC-VSS-11-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 3:36:11 03/22/2007 02:41a 1,736 TC-VSS-13-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 5:14:40 03/22/2007 04:08a 1,736 TC-VSS-15-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 6:42:27 03/22/2007 05:41a 1,736 TC-VSS-17-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 8:09:01 03/22/2007 06:54a 1,736 TC-VSS-19-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 9:42:19 03/22/2007 08:06a 1,738 TC-VSS-21-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 10:55:17 03/22/2007 09:18a 1,738 TC-VSS-23-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 12:07:00 03/22/2007 10:51a 1,742 TC-VSS-25-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 13:18:33 03/22/2007 10:44a 82 TC-VSS-28-.output.logs.txt [22.03.2007 10:44:39] Use VSS 6.0 SSAPI 03/21/2007 08:27p 1,764 TC-VSS-3-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 21.03.2007 23:14:42 03/22/2007 10:44a 82 TC-VSS-31-.output.logs.txt [22.03.2007 10:44:43] Use VSS 6.0 SSAPI 03/22/2007 12:41p 1,764 TC-VSS-33-.output.logs.txt History request from: 21.03.2007 18:57:47, to: 22.03.2007 14:52:27 03/22/2007 12:42p 174 TC-VSS-35-.output ]]>
03/22/2007 03:37p 14,598 TC-VSS-35-.output.logs.txt History
request from: 21.03.2007 18:57:47, to: 22.03.2007 16:42:20
03/22/2007 12:42p 0 TC-VSS-36-.error
03/21/2007 09:47p 1,762 TC-VSS-5-.output.logs.txt History
request from: 21.03.2007 18:57:47, to: 22.03.2007 0:27:54
03/22/2007 05:06a 127,721,334 TC-VSS-7-.output.logs.txt Patch request
from: 01.01.1970, to: 21.03.2007 18:57:47
03/21/2007 11:35p 1,762 TC-VSS-9-.output.logs.txt History
request from: 21.03.2007 18:57:47, to: 22.03.2007 1:48:12


0
Comment actions Permalink

Raz,

We're trying to optimize the process of obtaining changes from VSS, though it is not trivial. I really hope TeamCity beta will contain optimized version of VSS module and the performance will be significantly improved.

Thanks for your help!

KIR

0
Comment actions Permalink

Hello Raz,

I've done major performance improvements to VSS support, could you please
try it.
Please, download attached file named vssSupport2007-03-23.zip. Do install
it please, do the following:
- stop teamcity server
- backup ]]>\webapps\ROOT\WEB-INF\classes
- unpack with overwrite all files from archive to classes folder
- start teamcity server

Initially it will start working under debug mode. To switch to release, please

copy classes\bin\release to classes\bin under WEB-INF folder. Before doing
this,
please shutdown web server.

File was attached to Jira issue TW-2118
created for that problem at http://www.jetbrains.net/jira/browse/TW-2118

Thanks!

--
Eugene Petrenko
JetBrains, Inc
http://www.jetbrains.com
"Develop with pleasure!"

Hello Eugene,

>> I've prepared a loggin version of TeamCity integration for you. It
>> will create files in the temp directory with names ending with
>> '.logs.txt'
>>

The results so far and a possible cause of the problem towards the end
of the message.

Upon starting the build, TC-VSS-1-.output.logs.txt was created and it
contains the following. 15 minutes have passed since starting the
build, nothing else has been added to the log. By monitoring
file/network, I can see that TC-VSS-NATIVE is actively working with
the VSS server, though.

Use VSS 6.0 SSAPI
History request from: 20.03.2007 19:33:05, to:
21.03.2007
20:13:11
History request for path: $/OURPROJECT
History request Root item: $/OURPROJECT,
HistoryRequest: visitNode spec=$/OURPROJECT
History request: VisitV spec $/OURPROJECT
version 08.03.2007
16:29:54
HistoryRequest: visitNode finish $/OURPROJECT
History request: Item $/OURPROJECT, before v=6,
after
v=6
ShouldVisitSubtree for $/OURPROJECT
Start get_Versions(VSSFLAG_RECURSYES, &versions)
Done get_Versions(VSSFLAG_RECURSYES, &versions)
teamcity.log:

INFO - ildTriggers.vcs.vss.VssSupport -
version from 1174419184970 to 1174507990606
INFO - SimpleCommandLineProcessRunner - Start process name:
e:\TeamCity\temp\TC-VSS-NATIVE-1174507987778.exe
e:\TeamCity\temp\TC-VSS-1-.output e:\TeamCity\temp\TC-VSS-2-.error
"C:\Program Files\Microsoft Visual Studio\VSS\srcsafe.ini" history
$/OURPROJECT 1174419184970 1174507990606
INFO - jetbrains.buildServer.Server - Agent dwcc01 has been
registered with id 1 currently runnung build -1 [2007-03-21
16:18:17,231] INFO - activities.log.ActivitiesLog - Configuration
added to queue; configurationName=continuous build; requestor=admin
INFO - activities.log.ActivitiesLog -
Build started; buildId=3 INFO -
activities.log.ActivitiesLog - Configuration removed from queue;
configurationName=continuous build

Filemon dump taken 20' after starting the build shows the
TC-VSS-NATIVE going through the files.

1 4:33:09 PM TC-VSS-NATIVE-1:21040 OPEN

VSSSERVER\VSS\data\e\evboaaaa SUCCESS
Options: Open Access: Read
2 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION

VSSSERVER\VSS\data\e\evboaaaa
SUCCESS FileFsDeviceInformation
3 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION

VSSSERVER\VSS\data\e\evboaaaa
SUCCESS FileStandardInformation
4 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\e\evboaaaa
SUCCESS Offset: 0 Length: 1024
5 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\e\evboaaaa
SUCCESS Offset: 0 Length: 4096
6 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\e\evboaaaa SUCCESS
Offset: 1024 Length: 1024
7 4:33:09 PM TC-VSS-NATIVE-1:21040 OPEN

VSSSERVER\VSS\data\c\cqbnaaaa SUCCESS
Options: Open Access: Read
8 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION

VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS FileFsDeviceInformation
9 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION

VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS FileStandardInformation
10 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS Offset: 0 Length: 1024
11 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS Offset: 0 Length: 4096
12 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS Offset: 1024 Length: 1024
13 4:33:09 PM TC-VSS-NATIVE-1:21040 CLOSE

VSSSERVER\VSS\data\e\evboaaaa
SUCCESS
14 4:33:09 PM TC-VSS-NATIVE-1:21040 OPEN

VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Options: Open Access: Read
15 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION

VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS FileFsDeviceInformation
16 4:33:09 PM TC-VSS-NATIVE-1:21040 QUERY INFORMATION

VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS FileStandardInformation
17 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Offset: 0 Length: 1024
18 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Offset: 0 Length: 4096
19 4:33:09 PM TC-VSS-NATIVE-1:21040 READ

VSSSERVER\VSS\data\m\mghmaaaa
SUCCESS Offset: 1024 Length: 1024
20 4:33:09 PM TC-VSS-NATIVE-1:21040 CLOSE

VSSSERVER\VSS\data\c\cqbnaaaa
SUCCESS
21 4:33:09 PM TC-VSS-NATIVE-1:21040 CLOSE

VSSSERVER\VSS\data\r\rghmaaaa
SUCCESS
I looked in one of the files it was searching (like

VSSSERVER\VSS\data\m\mghmaaaa). VSS seems to have 2 files/real file,
one is a wrapper with the real filename and other metadata, the second
one with the same name and extension like a or b (e.g. mghmaaaa.a) is
the latest version.

However, this particular file is NOT under $/OURPROJECT but under a
different one (like $/REALLYOLDPROJECT). There is no file with this
name for the version I set up TC to build. So, I speculate the native
client is parsing the entire VSS directory, not only $/OURPROJECT. It
may ignore those other projects afterwards, but it still reads
information about them and thus adding to the processing time.

HTH,
Raz



0
Comment actions Permalink

Hello Eugene,

Hello Raz,

I've done major performance improvements to VSS support, could you
please try it.


Major indeed :) This time checking for changes took 2 minutes :)

Excellent, thanks!


0

Please sign in to leave a comment.